Query about long latency issue with Mybatis

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

Query about long latency issue with Mybatis

wenxing zheng
Dear all,

I have a Spring application with Mybatis to do the update and select on MySQL database. From the metrics stats on Datadog, we found the total elapsed time almost equals to the Mybatis operation time. 

As our update and select are both against the Primary key, the latency stats hit to more than 100ms, but we didn't find 100ms slow log on database. That's quite puzzle me. Attached is our stats screenshot, please advice what would be the problem here:

<a imageanchor="1" href="about:invalid#zClosurez" style="clear: left; margin-bottom: 1em; float: left; margin-right: 1em;">15_45_21__10_19_2018.jpg

















The versions of corresponding version are listed below:
  • mybatis - 3.4.0
  • spring boot - 1.5.2
  • hikaricp - 2.7.3
Thank you very much.
Regards, Wenxing

--
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: Query about long latency issue with Mybatis

Iwao AVE!
Hi Wenxing,

First, you need to find out which statement is slow.
Then post the details i.e. relevant Java code, mapper, result map, configurations, etc..

Alternatively, if you could provide a small project that reproduces the latency issue, we may be able to give you a solution (or explanation at least) quickly.

Regards,
Iwao


On Fri, Oct 19, 2018 at 4:49 PM wenxing zheng <[hidden email]> wrote:
Dear all,

I have a Spring application with Mybatis to do the update and select on MySQL database. From the metrics stats on Datadog, we found the total elapsed time almost equals to the Mybatis operation time. 

As our update and select are both against the Primary key, the latency stats hit to more than 100ms, but we didn't find 100ms slow log on database. That's quite puzzle me. Attached is our stats screenshot, please advice what would be the problem here:

15_45_21__10_19_2018.jpg

















The versions of corresponding version are listed below:
  • mybatis - 3.4.0
  • spring boot - 1.5.2
  • hikaricp - 2.7.3
Thank you very much.
Regards, Wenxing

--
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: Query about long latency issue with Mybatis

wenxing zheng
Thanks to Iwao.

Sorry that I can't provide all the information as required by the security department. The followings are some of the code snippets

public void internalSubmitCancel(Long userId, Long orderId) {
 
// 验证用户和订单id的关系。
  Map<String, Object> map = new HashMap<>();
  map
.put("orderId", orderId);
  map
.put("userId", userId);
 
OrderAction orderAction = orderMapper.selectAction(map); // MySQL table creates an index on the f_order_id column
}

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE mapper PUBLIC "-//mybatis.org//DTD Mapper 3.0//EN" "org/apache/ibatis/builder/xml/mybatis-3-mapper.dtd">
<mapper namespace="com.mycomp.order.repository.OrderMapper">
 
<resultMap id="BaseResultMap" type="com.mycomp.order.model.OrderAction">
   
<id column="f_id" jdbcType="BIGINT" property="id" />
   
<result column="f_version" jdbcType="BIGINT" property="version" />
   
<result column="f_created_at" jdbcType="BIGINT" property="createdAt" />
   
<result column="f_updated_at" jdbcType="BIGINT" property="updatedAt" />
   
<result column="f_type" jdbcType="TINYINT" property="type" />
   
<result column="f_order_id" jdbcType="BIGINT" property="orderId" />
   
<result column="f_symbol" jdbcType="VARCHAR" property="symbol" />
   
<result column="f_state" jdbcType="TINYINT" property="state" />
   
<result column="f_action_type" jdbcType="TINYINT" property="actionType" />
   
<result column="f_account_id" jdbcType="BIGINT" property="accountId" />
   
<result column="f_user_id" jdbcType="BIGINT" property="userId" />
   
<result column="f_source" jdbcType="TINYINT" property="source" />
 
</resultMap>

 
<sql id="Base_Column_List">
    f_id, f_version, f_created_at, f_updated_at, f_type, f_order_id, f_symbol, f_state, f_action_type, f_account_id, f_user_id, f_source
 
</sql>

 
<select id="selectAction" resultMap="BaseResultMap">
    SELECT
<include refid="Base_Column_List" />
    FROM t_order_action
    WHERE f_order_id
= #{orderId}
    AND f_user_id
= #{userId}
    ORDER BY f_id DESC LIMIT
1
 
</select>
Enter code here...

And we have an interceptor to monitor the elapsed time of mappers:
@Slf4j
@Intercepts({
   
@Signature(type = Executor.class, method = "query", args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class, CacheKey.class, BoundSql.class}),
   
@Signature(type = Executor.class, method = "query", args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class}),
   
@Signature(type = Executor.class, method = "update", args = {MappedStatement.class, Object.class})
})
@Component
public class MyBatisPerfInterceptor implements Interceptor {
 
private static final String GLOBAL_METRIC_NAME = "mybatis_mapper_method";
 
private static final String GLOBAL_METRIC_NAME_CPUTIME = "mybatis_mapper_method_cputime";

 
private Properties properties;

 
@Autowired
  private StatsdClient statsd;

 
@Override
  public Object intercept(Invocation invocation) throws Throwable {
   
String mapperId = "unknownMapperId";
   
String className = "unknownClass";
   
String methodName = "unknownMethod";
   
String sqlType = "unknownType";

   
try {
     
MappedStatement mappedStatement = (MappedStatement) invocation.getArgs()[0];
      mapperId
= mappedStatement.getId();
     
String[] segments = mapperId.split("\\.");
      className
= segments[segments.length - 2];
      methodName
= segments[segments.length - 1];
      sqlType
= mappedStatement.getSqlCommandType().name();
   
} catch (Exception e) {
     
log.error("failed to capture mybatis method name : {}", mapperId, e);
   
}

   
long start = HuobiDateUtil.currentTimeMillis();
   
Object res = invocation.proceed();
   
long end = HuobiDateUtil.currentTimeMillis();

   
statsd.histogram(GLOBAL_METRIC_NAME, end - start, "method:" + className + "_" + methodName, "sqlType:" + sqlType);

   
return res;
 
}

From the Datadog stats, sometimes the selectAction method tooks more than 3s. But we can't see the corresponding slow log on the DB server. 


On Saturday, October 20, 2018 at 10:22:19 AM UTC+8, Iwao AVE! wrote:
Hi Wenxing,

First, you need to find out which statement is slow.
Then post the details i.e. relevant Java code, mapper, result map, configurations, etc..

Alternatively, if you could provide a small project that reproduces the latency issue, we may be able to give you a solution (or explanation at least) quickly.

Regards,
Iwao


On Fri, Oct 19, 2018 at 4:49 PM wenxing zheng <<a href="javascript:" target="_blank" gdf-obfuscated-mailto="osnwpwNLBgAJ" rel="nofollow" onmousedown="this.href=&#39;javascript:&#39;;return true;" onclick="this.href=&#39;javascript:&#39;;return true;">wenxin...@...> wrote:
Dear all,

I have a Spring application with Mybatis to do the update and select on MySQL database. From the metrics stats on Datadog, we found the total elapsed time almost equals to the Mybatis operation time. 

As our update and select are both against the Primary key, the latency stats hit to more than 100ms, but we didn't find 100ms slow log on database. That's quite puzzle me. Attached is our stats screenshot, please advice what would be the problem here:

15_45_21__10_19_2018.jpg

















The versions of corresponding version are listed below:
  • mybatis - 3.4.0
  • spring boot - 1.5.2
  • hikaricp - 2.7.3
Thank you very much.
Regards, Wenxing

--
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="osnwpwNLBgAJ" 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: Query about long latency issue with Mybatis

wenxing zheng
In reply to this post by wenxing zheng
Thanks to Iwao.

Please find the code snippets below for reference. 


//Application Logic

 
public void internalSubmitCancel(Long userId, Long orderId) {  Map<String, Object> map = new HashMap<>();
  map
.put("orderId", orderId);
  map
.put("userId", userId);
 
//From the metric stats on Datadog, the selectAction took more than 1s very ofthen. And we didn't find the corresponding slow log on DB server
 
//although we set the slow log threshold to 200ms. That's quite puzzled me
 
OrderAction orderAction = actionMapper.selectAction(map);
 
...
}

//BatisMapper
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE mapper PUBLIC "-//mybatis.org//DTD Mapper 3.0//EN" "org/apache/ibatis/builder/xml/mybatis-3-mapper.dtd">
<mapper namespace="com.mycomp.repository.ActionMapper">
 
<resultMap id="BaseResultMap" type="com.mycomp.model.OrderAction">
   
<id column="f_id" jdbcType="BIGINT" property="id" />
   
<result column="f_version" jdbcType="BIGINT" property="version" />
   
<result column="f_created_at" jdbcType="BIGINT" property="createdAt" />
   
<result column="f_updated_at" jdbcType="BIGINT" property="updatedAt" />
   
<result column="f_type" jdbcType="TINYINT" property="type" />
   
<result column="f_order_id" jdbcType="BIGINT" property="orderId" />
   
<result column="f_user_id" jdbcType="BIGINT" property="userId" />
   
...
 
</resultMap>
  <sql id="Base_Column_List">
    f_id, f_version, f_created_at, f_updated_at, f_type, f_order_id, f_user_id...
  </
sql>

 
<select id="selectAction" resultMap="BaseResultMap">
    SELECT
<include refid="Base_Column_List" />
    FROM t_action
    WHERE f_order_id
= #{orderId}
    AND f_user_id
= #{userId}
    ORDER BY f_id DESC LIMIT
1
 
</select>

/
/Mybatis Interceptor
@Slf4j
@Intercepts({
   
@Signature(type = Executor.class, method = "query", args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class, CacheKey.class, BoundSql.class}),
   
@Signature(type = Executor.class, method = "query", args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class}),
   
@Signature(type = Executor.class, method = "update", args = {MappedStatement.class, Object.class})
})
@Component
public class MyBatisPerfInterceptor implements Interceptor {
 
private static final String GLOBAL_METRIC_NAME = "mybatis_mapper_method";
 
private static final String GLOBAL_METRIC_NAME_CPUTIME = "mybatis_mapper_method_cputime";

 
private Properties properties;

 
@Autowired
 
private StatsdClient statsd;

 
@Override
 
public Object intercept(Invocation invocation) throws Throwable {
   
String mapperId = "unknownMapperId";
   
String className = "unknownClass";
   
String methodName = "unknownMethod";
   
String sqlType = "unknownType";

   
try {
     
MappedStatement mappedStatement = (MappedStatement) invocation.getArgs()[0];
      mapperId
= mappedStatement.getId();
     
String[] segments = mapperId.split("\\.");
      className
= segments[segments.length - 2];
      methodName
= segments[segments.length - 1];
      sqlType
= mappedStatement.getSqlCommandType().name();
   
} catch (Exception e) {
      log
.error("failed to capture mybatis method name : {}", mapperId, e);
   
}

   
long start = DateUtil.currentTimeMillis();
   
Object res = invocation.proceed();
   
long end = DateUtil.currentTimeMillis();

    statsd
.histogram(GLOBAL_METRIC_NAME, end - start, "method:" + className + "_" + methodName, "sqlType:" + sqlType);

   
return res;
 
}



--
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: Query about long latency issue with Mybatis

Iwao AVE!
Hi Wenxing,

The query returns one row and the result map does not have <collection
/> nor <association />, so I'm not sure why it's slow.

I would suggest you to create a small project with a minimum setup (no
spring, no interceptors) as I did in the other thread [1].
If it's still slow, upload the project to your repository and I'll
take a look when I have some time (you can use different
table/column/object names if necessary).
If it's fast, add extra stuff like interceptor one by one and you will
find the cause eventually.

Another option is to use a profiler like VisualVM [2].

Regards,
Iwao

[1] https://groups.google.com/d/msg/mybatis-user/Wubq26QCWYo/GYmXYWS0AgAJ
[2] https://visualvm.github.io/



On Thu, Oct 25, 2018 at 5:58 PM wenxing zheng <[hidden email]> wrote:

>
> Thanks to Iwao.
>
>
> Please find the code snippets below for reference.
>
>
>
> //Application Logic
>
>  public void internalSubmitCancel(Long userId, Long orderId) {  Map<String, Object> map = new HashMap<>();
>   map.put("orderId", orderId);
>   map.put("userId", userId);
>   //From the metric stats on Datadog, the selectAction took more than 1s very ofthen. And we didn't find the corresponding slow log on DB server
>   //although we set the slow log threshold to 200ms. That's quite puzzled me
>   OrderAction orderAction = actionMapper.selectAction(map);
>   ...
> }
>
> //BatisMapper
> <?xml version="1.0" encoding="UTF-8"?>
> <!DOCTYPE mapper PUBLIC "-//mybatis.org//DTD Mapper 3.0//EN" "org/apache/ibatis/builder/xml/mybatis-3-mapper.dtd">
> <mapper namespace="com.mycomp.repository.ActionMapper">
>   <resultMap id="BaseResultMap" type="com.mycomp.model.OrderAction">
>     <id column="f_id" jdbcType="BIGINT" property="id" />
>     <result column="f_version" jdbcType="BIGINT" property="version" />
>     <result column="f_created_at" jdbcType="BIGINT" property="createdAt" />
>     <result column="f_updated_at" jdbcType="BIGINT" property="updatedAt" />
>     <result column="f_type" jdbcType="TINYINT" property="type" />
>     <result column="f_order_id" jdbcType="BIGINT" property="orderId" />
>     <result column="f_user_id" jdbcType="BIGINT" property="userId" />
>     ...
>   </resultMap>
>   <sql id="Base_Column_List">
>     f_id, f_version, f_created_at, f_updated_at, f_type, f_order_id, f_user_id...
>   </sql>
>
>   <select id="selectAction" resultMap="BaseResultMap">
>     SELECT <include refid="Base_Column_List" />
>     FROM t_action
>     WHERE f_order_id = #{orderId}
>     AND f_user_id = #{userId}
>     ORDER BY f_id DESC LIMIT 1
>   </select>
>
> //Mybatis Interceptor
> @Slf4j
> @Intercepts({
>     @Signature(type = Executor.class, method = "query", args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class, CacheKey.class, BoundSql.class}),
>     @Signature(type = Executor.class, method = "query", args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class}),
>     @Signature(type = Executor.class, method = "update", args = {MappedStatement.class, Object.class})
> })
> @Component
> public class MyBatisPerfInterceptor implements Interceptor {
>   private static final String GLOBAL_METRIC_NAME = "mybatis_mapper_method";
>   private static final String GLOBAL_METRIC_NAME_CPUTIME = "mybatis_mapper_method_cputime";
>
>   private Properties properties;
>
>   @Autowired
>   private StatsdClient statsd;
>
>   @Override
>   public Object intercept(Invocation invocation) throws Throwable {
>     String mapperId = "unknownMapperId";
>     String className = "unknownClass";
>     String methodName = "unknownMethod";
>     String sqlType = "unknownType";
>
>     try {
>       MappedStatement mappedStatement = (MappedStatement) invocation.getArgs()[0];
>       mapperId = mappedStatement.getId();
>       String[] segments = mapperId.split("\\.");
>       className = segments[segments.length - 2];
>       methodName = segments[segments.length - 1];
>       sqlType = mappedStatement.getSqlCommandType().name();
>     } catch (Exception e) {
>       log.error("failed to capture mybatis method name : {}", mapperId, e);
>     }
>
>     long start = DateUtil.currentTimeMillis();
>     Object res = invocation.proceed();
>     long end = DateUtil.currentTimeMillis();
>
>     statsd.histogram(GLOBAL_METRIC_NAME, end - start, "method:" + className + "_" + methodName, "sqlType:" + sqlType);
>
>     return res;
>   }
>
>
>
> --
> 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.
Tim
Reply | Threaded
Open this post in threaded view
|

Re: Query about long latency issue with Mybatis

Tim
I know you said the queries are hitting primary keys but can you check an explain plan just to be sure? Also are you getting lock contention on the db? Is your pool size too small or is this reproducible w just a single user/query?


> On Oct 26, 2018, at 13:02, Iwao AVE! <[hidden email]> wrote:
>
> Hi Wenxing,
>
> The query returns one row and the result map does not have <collection
> /> nor <association />, so I'm not sure why it's slow.
>
> I would suggest you to create a small project with a minimum setup (no
> spring, no interceptors) as I did in the other thread [1].
> If it's still slow, upload the project to your repository and I'll
> take a look when I have some time (you can use different
> table/column/object names if necessary).
> If it's fast, add extra stuff like interceptor one by one and you will
> find the cause eventually.
>
> Another option is to use a profiler like VisualVM [2].
>
> Regards,
> Iwao
>
> [1] https://groups.google.com/d/msg/mybatis-user/Wubq26QCWYo/GYmXYWS0AgAJ
> [2] https://visualvm.github.io/
>
>
>
>> On Thu, Oct 25, 2018 at 5:58 PM wenxing zheng <[hidden email]> wrote:
>>
>> Thanks to Iwao.
>>
>>
>> Please find the code snippets below for reference.
>>
>>
>>
>> //Application Logic
>>
>> public void internalSubmitCancel(Long userId, Long orderId) {  Map<String, Object> map = new HashMap<>();
>>  map.put("orderId", orderId);
>>  map.put("userId", userId);
>>  //From the metric stats on Datadog, the selectAction took more than 1s very ofthen. And we didn't find the corresponding slow log on DB server
>>  //although we set the slow log threshold to 200ms. That's quite puzzled me
>>  OrderAction orderAction = actionMapper.selectAction(map);
>>  ...
>> }
>>
>> //BatisMapper
>> <?xml version="1.0" encoding="UTF-8"?>
>> <!DOCTYPE mapper PUBLIC "-//mybatis.org//DTD Mapper 3.0//EN" "org/apache/ibatis/builder/xml/mybatis-3-mapper.dtd">
>> <mapper namespace="com.mycomp.repository.ActionMapper">
>>  <resultMap id="BaseResultMap" type="com.mycomp.model.OrderAction">
>>    <id column="f_id" jdbcType="BIGINT" property="id" />
>>    <result column="f_version" jdbcType="BIGINT" property="version" />
>>    <result column="f_created_at" jdbcType="BIGINT" property="createdAt" />
>>    <result column="f_updated_at" jdbcType="BIGINT" property="updatedAt" />
>>    <result column="f_type" jdbcType="TINYINT" property="type" />
>>    <result column="f_order_id" jdbcType="BIGINT" property="orderId" />
>>    <result column="f_user_id" jdbcType="BIGINT" property="userId" />
>>    ...
>>  </resultMap>
>>  <sql id="Base_Column_List">
>>    f_id, f_version, f_created_at, f_updated_at, f_type, f_order_id, f_user_id...
>>  </sql>
>>
>>  <select id="selectAction" resultMap="BaseResultMap">
>>    SELECT <include refid="Base_Column_List" />
>>    FROM t_action
>>    WHERE f_order_id = #{orderId}
>>    AND f_user_id = #{userId}
>>    ORDER BY f_id DESC LIMIT 1
>>  </select>
>>
>> //Mybatis Interceptor
>> @Slf4j
>> @Intercepts({
>>    @Signature(type = Executor.class, method = "query", args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class, CacheKey.class, BoundSql.class}),
>>    @Signature(type = Executor.class, method = "query", args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class}),
>>    @Signature(type = Executor.class, method = "update", args = {MappedStatement.class, Object.class})
>> })
>> @Component
>> public class MyBatisPerfInterceptor implements Interceptor {
>>  private static final String GLOBAL_METRIC_NAME = "mybatis_mapper_method";
>>  private static final String GLOBAL_METRIC_NAME_CPUTIME = "mybatis_mapper_method_cputime";
>>
>>  private Properties properties;
>>
>>  @Autowired
>>  private StatsdClient statsd;
>>
>>  @Override
>>  public Object intercept(Invocation invocation) throws Throwable {
>>    String mapperId = "unknownMapperId";
>>    String className = "unknownClass";
>>    String methodName = "unknownMethod";
>>    String sqlType = "unknownType";
>>
>>    try {
>>      MappedStatement mappedStatement = (MappedStatement) invocation.getArgs()[0];
>>      mapperId = mappedStatement.getId();
>>      String[] segments = mapperId.split("\\.");
>>      className = segments[segments.length - 2];
>>      methodName = segments[segments.length - 1];
>>      sqlType = mappedStatement.getSqlCommandType().name();
>>    } catch (Exception e) {
>>      log.error("failed to capture mybatis method name : {}", mapperId, e);
>>    }
>>
>>    long start = DateUtil.currentTimeMillis();
>>    Object res = invocation.proceed();
>>    long end = DateUtil.currentTimeMillis();
>>
>>    statsd.histogram(GLOBAL_METRIC_NAME, end - start, "method:" + className + "_" + methodName, "sqlType:" + sqlType);
>>
>>    return res;
>>  }
>>
>>
>>
>> --
>> 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.

--
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: Query about long latency issue with Mybatis

wenxing zheng
The explain plan should be ok, as I have checked with DBA for many times and we didn't see the slow log on MySQL server. 

But I think the issue should be related with the DB status during the query, but I have no evidence. From the stats, the proportion of long latency is very small since we have massive queries/updates, but the issue did happen regularly. 

Thanks to h3adache.

On Saturday, October 27, 2018 at 2:43:29 AM UTC+8, h3adache wrote:
I know you said the queries are hitting primary keys but can you check an explain plan just to be sure? Also are you getting lock contention on the db? Is your pool size too small or is this reproducible w just a single user/query?


> On Oct 26, 2018, at 13:02, Iwao AVE! <<a href="javascript:" target="_blank" gdf-obfuscated-mailto="uDk7cgibCQAJ" rel="nofollow" onmousedown="this.href=&#39;javascript:&#39;;return true;" onclick="this.href=&#39;javascript:&#39;;return true;">hara...@...> wrote:
>
> Hi Wenxing,
>
> The query returns one row and the result map does not have <collection
> /> nor <association />, so I'm not sure why it's slow.
>
> I would suggest you to create a small project with a minimum setup (no
> spring, no interceptors) as I did in the other thread [1].
> If it's still slow, upload the project to your repository and I'll
> take a look when I have some time (you can use different
> table/column/object names if necessary).
> If it's fast, add extra stuff like interceptor one by one and you will
> find the cause eventually.
>
> Another option is to use a profiler like VisualVM [2].
>
> Regards,
> Iwao
>
> [1] <a href="https://groups.google.com/d/msg/mybatis-user/Wubq26QCWYo/GYmXYWS0AgAJ" target="_blank" rel="nofollow" onmousedown="this.href=&#39;https://groups.google.com/d/msg/mybatis-user/Wubq26QCWYo/GYmXYWS0AgAJ&#39;;return true;" onclick="this.href=&#39;https://groups.google.com/d/msg/mybatis-user/Wubq26QCWYo/GYmXYWS0AgAJ&#39;;return true;">https://groups.google.com/d/msg/mybatis-user/Wubq26QCWYo/GYmXYWS0AgAJ
> [2] <a href="https://visualvm.github.io/" target="_blank" rel="nofollow" onmousedown="this.href=&#39;https://www.google.com/url?q\x3dhttps%3A%2F%2Fvisualvm.github.io%2F\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNFMFod8rwAD5ap9u7-RX7XgkcFxzQ&#39;;return true;" onclick="this.href=&#39;https://www.google.com/url?q\x3dhttps%3A%2F%2Fvisualvm.github.io%2F\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNFMFod8rwAD5ap9u7-RX7XgkcFxzQ&#39;;return true;">https://visualvm.github.io/
>
>
>
>> On Thu, Oct 25, 2018 at 5:58 PM wenxing zheng <<a href="javascript:" target="_blank" gdf-obfuscated-mailto="uDk7cgibCQAJ" rel="nofollow" onmousedown="this.href=&#39;javascript:&#39;;return true;" onclick="this.href=&#39;javascript:&#39;;return true;">wenxin...@...> wrote:
>>
>> Thanks to Iwao.
>>
>>
>> Please find the code snippets below for reference.
>>
>>
>>
>> //Application Logic
>>
>> public void internalSubmitCancel(Long userId, Long orderId) {  Map<String, Object> map = new HashMap<>();
>>  map.put("orderId", orderId);
>>  map.put("userId", userId);
>>  //From the metric stats on Datadog, the selectAction took more than 1s very ofthen. And we didn't find the corresponding slow log on DB server
>>  //although we set the slow log threshold to 200ms. That's quite puzzled me
>>  OrderAction orderAction = actionMapper.selectAction(map);
>>  ...
>> }
>>
>> //BatisMapper
>> <?xml version="1.0" encoding="UTF-8"?>
>> <!DOCTYPE mapper PUBLIC "-//<a href="http://mybatis.org//DTD" target="_blank" rel="nofollow" onmousedown="this.href=&#39;http://www.google.com/url?q\x3dhttp%3A%2F%2Fmybatis.org%2F%2FDTD\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNHjp-E8UL0TmmS7A0V54yMfbtfEkA&#39;;return true;" onclick="this.href=&#39;http://www.google.com/url?q\x3dhttp%3A%2F%2Fmybatis.org%2F%2FDTD\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNHjp-E8UL0TmmS7A0V54yMfbtfEkA&#39;;return true;">mybatis.org//DTD Mapper 3.0//EN" "org/apache/ibatis/builder/xml/mybatis-3-mapper.dtd">
>> <mapper namespace="com.mycomp.repository.ActionMapper">
>>  <resultMap id="BaseResultMap" type="com.mycomp.model.OrderAction">
>>    <id column="f_id" jdbcType="BIGINT" property="id" />
>>    <result column="f_version" jdbcType="BIGINT" property="version" />
>>    <result column="f_created_at" jdbcType="BIGINT" property="createdAt" />
>>    <result column="f_updated_at" jdbcType="BIGINT" property="updatedAt" />
>>    <result column="f_type" jdbcType="TINYINT" property="type" />
>>    <result column="f_order_id" jdbcType="BIGINT" property="orderId" />
>>    <result column="f_user_id" jdbcType="BIGINT" property="userId" />
>>    ...
>>  </resultMap>
>>  <sql id="Base_Column_List">
>>    f_id, f_version, f_created_at, f_updated_at, f_type, f_order_id, f_user_id...
>>  </sql>
>>
>>  <select id="selectAction" resultMap="BaseResultMap">
>>    SELECT <include refid="Base_Column_List" />
>>    FROM t_action
>>    WHERE f_order_id = #{orderId}
>>    AND f_user_id = #{userId}
>>    ORDER BY f_id DESC LIMIT 1
>>  </select>
>>
>> //Mybatis Interceptor
>> @Slf4j
>> @Intercepts({
>>    @Signature(type = Executor.class, method = "query", args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class, CacheKey.class, BoundSql.class}),
>>    @Signature(type = Executor.class, method = "query", args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class}),
>>    @Signature(type = Executor.class, method = "update", args = {MappedStatement.class, Object.class})
>> })
>> @Component
>> public class MyBatisPerfInterceptor implements Interceptor {
>>  private static final String GLOBAL_METRIC_NAME = "mybatis_mapper_method";
>>  private static final String GLOBAL_METRIC_NAME_CPUTIME = "mybatis_mapper_method_cputime";
>>
>>  private Properties properties;
>>
>>  @Autowired
>>  private StatsdClient statsd;
>>
>>  @Override
>>  public Object intercept(Invocation invocation) throws Throwable {
>>    String mapperId = "unknownMapperId";
>>    String className = "unknownClass";
>>    String methodName = "unknownMethod";
>>    String sqlType = "unknownType";
>>
>>    try {
>>      MappedStatement mappedStatement = (MappedStatement) invocation.getArgs()[0];
>>      mapperId = mappedStatement.getId();
>>      String[] segments = mapperId.split("\\.");
>>      className = segments[segments.length - 2];
>>      methodName = segments[segments.length - 1];
>>      sqlType = mappedStatement.getSqlCommandType().name();
>>    } catch (Exception e) {
>>      log.error("failed to capture mybatis method name : {}", mapperId, e);
>>    }
>>
>>    long start = DateUtil.currentTimeMillis();
>>    Object res = invocation.proceed();
>>    long end = DateUtil.currentTimeMillis();
>>
>>    statsd.histogram(GLOBAL_METRIC_NAME, end - start, "method:" + className + "_" + methodName, "sqlType:" + sqlType);
>>
>>    return res;
>>  }
>>
>>
>>
>> --
>> 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="uDk7cgibCQAJ" 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 <a href="javascript:" target="_blank" gdf-obfuscated-mailto="uDk7cgibCQAJ" 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: Query about long latency issue with Mybatis

wenxing zheng
In reply to this post by Iwao AVE!
Thanks to Iwao.

I will have a try to reproduce the issue with a small project. But if Mybatis can present the latency metrics for troubleshooting in the future, that would be much better.

On Saturday, October 27, 2018 at 1:03:20 AM UTC+8, Iwao AVE! wrote:
Hi Wenxing,

The query returns one row and the result map does not have <collection
/> nor <association />, so I'm not sure why it's slow.

I would suggest you to create a small project with a minimum setup (no
spring, no interceptors) as I did in the other thread [1].
If it's still slow, upload the project to your repository and I'll
take a look when I have some time (you can use different
table/column/object names if necessary).
If it's fast, add extra stuff like interceptor one by one and you will
find the cause eventually.

Another option is to use a profiler like VisualVM [2].

Regards,
Iwao

[1] <a href="https://groups.google.com/d/msg/mybatis-user/Wubq26QCWYo/GYmXYWS0AgAJ" target="_blank" rel="nofollow" onmousedown="this.href=&#39;https://groups.google.com/d/msg/mybatis-user/Wubq26QCWYo/GYmXYWS0AgAJ&#39;;return true;" onclick="this.href=&#39;https://groups.google.com/d/msg/mybatis-user/Wubq26QCWYo/GYmXYWS0AgAJ&#39;;return true;">https://groups.google.com/d/msg/mybatis-user/Wubq26QCWYo/GYmXYWS0AgAJ
[2] <a href="https://visualvm.github.io/" target="_blank" rel="nofollow" onmousedown="this.href=&#39;https://www.google.com/url?q\x3dhttps%3A%2F%2Fvisualvm.github.io%2F\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNFMFod8rwAD5ap9u7-RX7XgkcFxzQ&#39;;return true;" onclick="this.href=&#39;https://www.google.com/url?q\x3dhttps%3A%2F%2Fvisualvm.github.io%2F\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNFMFod8rwAD5ap9u7-RX7XgkcFxzQ&#39;;return true;">https://visualvm.github.io/



On Thu, Oct 25, 2018 at 5:58 PM wenxing zheng <<a href="javascript:" target="_blank" gdf-obfuscated-mailto="aYhyU5GVCQAJ" rel="nofollow" onmousedown="this.href=&#39;javascript:&#39;;return true;" onclick="this.href=&#39;javascript:&#39;;return true;">wenxin...@...> wrote:

>
> Thanks to Iwao.
>
>
> Please find the code snippets below for reference.
>
>
>
> //Application Logic
>
>  public void internalSubmitCancel(Long userId, Long orderId) {  Map<String, Object> map = new HashMap<>();
>   map.put("orderId", orderId);
>   map.put("userId", userId);
>   //From the metric stats on Datadog, the selectAction took more than 1s very ofthen. And we didn't find the corresponding slow log on DB server
>   //although we set the slow log threshold to 200ms. That's quite puzzled me
>   OrderAction orderAction = actionMapper.selectAction(map);
>   ...
> }
>
> //BatisMapper
> <?xml version="1.0" encoding="UTF-8"?>
> <!DOCTYPE mapper PUBLIC "-//<a href="http://mybatis.org//DTD" target="_blank" rel="nofollow" onmousedown="this.href=&#39;http://www.google.com/url?q\x3dhttp%3A%2F%2Fmybatis.org%2F%2FDTD\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNHjp-E8UL0TmmS7A0V54yMfbtfEkA&#39;;return true;" onclick="this.href=&#39;http://www.google.com/url?q\x3dhttp%3A%2F%2Fmybatis.org%2F%2FDTD\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNHjp-E8UL0TmmS7A0V54yMfbtfEkA&#39;;return true;">mybatis.org//DTD Mapper 3.0//EN" "org/apache/ibatis/builder/xml/mybatis-3-mapper.dtd">
> <mapper namespace="com.mycomp.repository.ActionMapper">
>   <resultMap id="BaseResultMap" type="com.mycomp.model.OrderAction">
>     <id column="f_id" jdbcType="BIGINT" property="id" />
>     <result column="f_version" jdbcType="BIGINT" property="version" />
>     <result column="f_created_at" jdbcType="BIGINT" property="createdAt" />
>     <result column="f_updated_at" jdbcType="BIGINT" property="updatedAt" />
>     <result column="f_type" jdbcType="TINYINT" property="type" />
>     <result column="f_order_id" jdbcType="BIGINT" property="orderId" />
>     <result column="f_user_id" jdbcType="BIGINT" property="userId" />
>     ...
>   </resultMap>
>   <sql id="Base_Column_List">
>     f_id, f_version, f_created_at, f_updated_at, f_type, f_order_id, f_user_id...
>   </sql>
>
>   <select id="selectAction" resultMap="BaseResultMap">
>     SELECT <include refid="Base_Column_List" />
>     FROM t_action
>     WHERE f_order_id = #{orderId}
>     AND f_user_id = #{userId}
>     ORDER BY f_id DESC LIMIT 1
>   </select>
>
> //Mybatis Interceptor
> @Slf4j
> @Intercepts({
>     @Signature(type = Executor.class, method = "query", args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class, CacheKey.class, BoundSql.class}),
>     @Signature(type = Executor.class, method = "query", args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class}),
>     @Signature(type = Executor.class, method = "update", args = {MappedStatement.class, Object.class})
> })
> @Component
> public class MyBatisPerfInterceptor implements Interceptor {
>   private static final String GLOBAL_METRIC_NAME = "mybatis_mapper_method";
>   private static final String GLOBAL_METRIC_NAME_CPUTIME = "mybatis_mapper_method_cputime";
>
>   private Properties properties;
>
>   @Autowired
>   private StatsdClient statsd;
>
>   @Override
>   public Object intercept(Invocation invocation) throws Throwable {
>     String mapperId = "unknownMapperId";
>     String className = "unknownClass";
>     String methodName = "unknownMethod";
>     String sqlType = "unknownType";
>
>     try {
>       MappedStatement mappedStatement = (MappedStatement) invocation.getArgs()[0];
>       mapperId = mappedStatement.getId();
>       String[] segments = mapperId.split("\\.");
>       className = segments[segments.length - 2];
>       methodName = segments[segments.length - 1];
>       sqlType = mappedStatement.getSqlCommandType().name();
>     } catch (Exception e) {
>       log.error("failed to capture mybatis method name : {}", mapperId, e);
>     }
>
>     long start = DateUtil.currentTimeMillis();
>     Object res = invocation.proceed();
>     long end = DateUtil.currentTimeMillis();
>
>     statsd.histogram(GLOBAL_METRIC_NAME, end - start, "method:" + className + "_" + methodName, "sqlType:" + sqlType);
>
>     return res;
>   }
>
>
>
> --
> 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="aYhyU5GVCQAJ" 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: Query about long latency issue with Mybatis

Iwao AVE!
It's not metrics, but DEBUG (or TRACE) level logging might give you
more detailed timeline.
With Spring, the following loggers are the relevant ones, IIRC.

- org.springframework.jdbc
- org.mybatis.spring
- com.mycomp.order.repository.OrderMapper (your mapper)

http://www.mybatis.org/mybatis-3/logging.html

// Iwao

On Mon, Oct 29, 2018 at 11:04 AM wenxing zheng <[hidden email]> wrote:

>
> Thanks to Iwao.
>
> I will have a try to reproduce the issue with a small project. But if Mybatis can present the latency metrics for troubleshooting in the future, that would be much better.
>
> On Saturday, October 27, 2018 at 1:03:20 AM UTC+8, Iwao AVE! wrote:
>>
>> Hi Wenxing,
>>
>> The query returns one row and the result map does not have <collection
>> /> nor <association />, so I'm not sure why it's slow.
>>
>> I would suggest you to create a small project with a minimum setup (no
>> spring, no interceptors) as I did in the other thread [1].
>> If it's still slow, upload the project to your repository and I'll
>> take a look when I have some time (you can use different
>> table/column/object names if necessary).
>> If it's fast, add extra stuff like interceptor one by one and you will
>> find the cause eventually.
>>
>> Another option is to use a profiler like VisualVM [2].
>>
>> Regards,
>> Iwao
>>
>> [1] https://groups.google.com/d/msg/mybatis-user/Wubq26QCWYo/GYmXYWS0AgAJ
>> [2] https://visualvm.github.io/
>>
>>
>>
>> On Thu, Oct 25, 2018 at 5:58 PM wenxing zheng <[hidden email]> wrote:
>> >
>> > Thanks to Iwao.
>> >
>> >
>> > Please find the code snippets below for reference.
>> >
>> >
>> >
>> > //Application Logic
>> >
>> >  public void internalSubmitCancel(Long userId, Long orderId) {  Map<String, Object> map = new HashMap<>();
>> >   map.put("orderId", orderId);
>> >   map.put("userId", userId);
>> >   //From the metric stats on Datadog, the selectAction took more than 1s very ofthen. And we didn't find the corresponding slow log on DB server
>> >   //although we set the slow log threshold to 200ms. That's quite puzzled me
>> >   OrderAction orderAction = actionMapper.selectAction(map);
>> >   ...
>> > }
>> >
>> > //BatisMapper
>> > <?xml version="1.0" encoding="UTF-8"?>
>> > <!DOCTYPE mapper PUBLIC "-//mybatis.org//DTD Mapper 3.0//EN" "org/apache/ibatis/builder/xml/mybatis-3-mapper.dtd">
>> > <mapper namespace="com.mycomp.repository.ActionMapper">
>> >   <resultMap id="BaseResultMap" type="com.mycomp.model.OrderAction">
>> >     <id column="f_id" jdbcType="BIGINT" property="id" />
>> >     <result column="f_version" jdbcType="BIGINT" property="version" />
>> >     <result column="f_created_at" jdbcType="BIGINT" property="createdAt" />
>> >     <result column="f_updated_at" jdbcType="BIGINT" property="updatedAt" />
>> >     <result column="f_type" jdbcType="TINYINT" property="type" />
>> >     <result column="f_order_id" jdbcType="BIGINT" property="orderId" />
>> >     <result column="f_user_id" jdbcType="BIGINT" property="userId" />
>> >     ...
>> >   </resultMap>
>> >   <sql id="Base_Column_List">
>> >     f_id, f_version, f_created_at, f_updated_at, f_type, f_order_id, f_user_id...
>> >   </sql>
>> >
>> >   <select id="selectAction" resultMap="BaseResultMap">
>> >     SELECT <include refid="Base_Column_List" />
>> >     FROM t_action
>> >     WHERE f_order_id = #{orderId}
>> >     AND f_user_id = #{userId}
>> >     ORDER BY f_id DESC LIMIT 1
>> >   </select>
>> >
>> > //Mybatis Interceptor
>> > @Slf4j
>> > @Intercepts({
>> >     @Signature(type = Executor.class, method = "query", args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class, CacheKey.class, BoundSql.class}),
>> >     @Signature(type = Executor.class, method = "query", args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class}),
>> >     @Signature(type = Executor.class, method = "update", args = {MappedStatement.class, Object.class})
>> > })
>> > @Component
>> > public class MyBatisPerfInterceptor implements Interceptor {
>> >   private static final String GLOBAL_METRIC_NAME = "mybatis_mapper_method";
>> >   private static final String GLOBAL_METRIC_NAME_CPUTIME = "mybatis_mapper_method_cputime";
>> >
>> >   private Properties properties;
>> >
>> >   @Autowired
>> >   private StatsdClient statsd;
>> >
>> >   @Override
>> >   public Object intercept(Invocation invocation) throws Throwable {
>> >     String mapperId = "unknownMapperId";
>> >     String className = "unknownClass";
>> >     String methodName = "unknownMethod";
>> >     String sqlType = "unknownType";
>> >
>> >     try {
>> >       MappedStatement mappedStatement = (MappedStatement) invocation.getArgs()[0];
>> >       mapperId = mappedStatement.getId();
>> >       String[] segments = mapperId.split("\\.");
>> >       className = segments[segments.length - 2];
>> >       methodName = segments[segments.length - 1];
>> >       sqlType = mappedStatement.getSqlCommandType().name();
>> >     } catch (Exception e) {
>> >       log.error("failed to capture mybatis method name : {}", mapperId, e);
>> >     }
>> >
>> >     long start = DateUtil.currentTimeMillis();
>> >     Object res = invocation.proceed();
>> >     long end = DateUtil.currentTimeMillis();
>> >
>> >     statsd.histogram(GLOBAL_METRIC_NAME, end - start, "method:" + className + "_" + methodName, "sqlType:" + sqlType);
>> >
>> >     return res;
>> >   }
>> >
>> >
>> >
>> > --
>> > 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.

--
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: Query about long latency issue with Mybatis

wenxing zheng

Got a call graph from appdynamics for your reference. It seems the com.zaxxer.hikari.pool.ProxyPreparedStatement:execute took more time than the actual time of SQL?



10_13_36__10_30_2018.jpg





On Monday, October 29, 2018 at 10:19:48 PM UTC+8, Iwao AVE! wrote:
It's not metrics, but DEBUG (or TRACE) level logging might give you
more detailed timeline.
With Spring, the following loggers are the relevant ones, IIRC.

- org.springframework.jdbc
- org.mybatis.spring
- com.mycomp.order.repository.OrderMapper (your mapper)

<a href="http://www.mybatis.org/mybatis-3/logging.html" target="_blank" rel="nofollow" onmousedown="this.href=&#39;http://www.google.com/url?q\x3dhttp%3A%2F%2Fwww.mybatis.org%2Fmybatis-3%2Flogging.html\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNHlXS48wRPdBD_gGWtDijqfgLbdgQ&#39;;return true;" onclick="this.href=&#39;http://www.google.com/url?q\x3dhttp%3A%2F%2Fwww.mybatis.org%2Fmybatis-3%2Flogging.html\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNHlXS48wRPdBD_gGWtDijqfgLbdgQ&#39;;return true;">http://www.mybatis.org/mybatis-3/logging.html

// Iwao

On Mon, Oct 29, 2018 at 11:04 AM wenxing zheng <<a href="javascript:" target="_blank" gdf-obfuscated-mailto="75ERlWJ4CgAJ" rel="nofollow" onmousedown="this.href=&#39;javascript:&#39;;return true;" onclick="this.href=&#39;javascript:&#39;;return true;">wenxin...@...> wrote:

>
> Thanks to Iwao.
>
> I will have a try to reproduce the issue with a small project. But if Mybatis can present the latency metrics for troubleshooting in the future, that would be much better.
>
> On Saturday, October 27, 2018 at 1:03:20 AM UTC+8, Iwao AVE! wrote:
>>
>> Hi Wenxing,
>>
>> The query returns one row and the result map does not have <collection
>> /> nor <association />, so I'm not sure why it's slow.
>>
>> I would suggest you to create a small project with a minimum setup (no
>> spring, no interceptors) as I did in the other thread [1].
>> If it's still slow, upload the project to your repository and I'll
>> take a look when I have some time (you can use different
>> table/column/object names if necessary).
>> If it's fast, add extra stuff like interceptor one by one and you will
>> find the cause eventually.
>>
>> Another option is to use a profiler like VisualVM [2].
>>
>> Regards,
>> Iwao
>>
>> [1] <a href="https://groups.google.com/d/msg/mybatis-user/Wubq26QCWYo/GYmXYWS0AgAJ" target="_blank" rel="nofollow" onmousedown="this.href=&#39;https://groups.google.com/d/msg/mybatis-user/Wubq26QCWYo/GYmXYWS0AgAJ&#39;;return true;" onclick="this.href=&#39;https://groups.google.com/d/msg/mybatis-user/Wubq26QCWYo/GYmXYWS0AgAJ&#39;;return true;">https://groups.google.com/d/msg/mybatis-user/Wubq26QCWYo/GYmXYWS0AgAJ
>> [2] <a href="https://visualvm.github.io/" target="_blank" rel="nofollow" onmousedown="this.href=&#39;https://www.google.com/url?q\x3dhttps%3A%2F%2Fvisualvm.github.io%2F\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNFMFod8rwAD5ap9u7-RX7XgkcFxzQ&#39;;return true;" onclick="this.href=&#39;https://www.google.com/url?q\x3dhttps%3A%2F%2Fvisualvm.github.io%2F\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNFMFod8rwAD5ap9u7-RX7XgkcFxzQ&#39;;return true;">https://visualvm.github.io/
>>
>>
>>
>> On Thu, Oct 25, 2018 at 5:58 PM wenxing zheng <[hidden email]> wrote:
>> >
>> > Thanks to Iwao.
>> >
>> >
>> > Please find the code snippets below for reference.
>> >
>> >
>> >
>> > //Application Logic
>> >
>> >  public void internalSubmitCancel(Long userId, Long orderId) {  Map<String, Object> map = new HashMap<>();
>> >   map.put("orderId", orderId);
>> >   map.put("userId", userId);
>> >   //From the metric stats on Datadog, the selectAction took more than 1s very ofthen. And we didn't find the corresponding slow log on DB server
>> >   //although we set the slow log threshold to 200ms. That's quite puzzled me
>> >   OrderAction orderAction = actionMapper.selectAction(map);
>> >   ...
>> > }
>> >
>> > //BatisMapper
>> > <?xml version="1.0" encoding="UTF-8"?>
>> > <!DOCTYPE mapper PUBLIC "-//<a href="http://mybatis.org//DTD" target="_blank" rel="nofollow" onmousedown="this.href=&#39;http://www.google.com/url?q\x3dhttp%3A%2F%2Fmybatis.org%2F%2FDTD\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNHjp-E8UL0TmmS7A0V54yMfbtfEkA&#39;;return true;" onclick="this.href=&#39;http://www.google.com/url?q\x3dhttp%3A%2F%2Fmybatis.org%2F%2FDTD\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNHjp-E8UL0TmmS7A0V54yMfbtfEkA&#39;;return true;">mybatis.org//DTD Mapper 3.0//EN" "org/apache/ibatis/builder/xml/mybatis-3-mapper.dtd">
>> > <mapper namespace="com.mycomp.repository.ActionMapper">
>> >   <resultMap id="BaseResultMap" type="com.mycomp.model.OrderAction">
>> >     <id column="f_id" jdbcType="BIGINT" property="id" />
>> >     <result column="f_version" jdbcType="BIGINT" property="version" />
>> >     <result column="f_created_at" jdbcType="BIGINT" property="createdAt" />
>> >     <result column="f_updated_at" jdbcType="BIGINT" property="updatedAt" />
>> >     <result column="f_type" jdbcType="TINYINT" property="type" />
>> >     <result column="f_order_id" jdbcType="BIGINT" property="orderId" />
>> >     <result column="f_user_id" jdbcType="BIGINT" property="userId" />
>> >     ...
>> >   </resultMap>
>> >   <sql id="Base_Column_List">
>> >     f_id, f_version, f_created_at, f_updated_at, f_type, f_order_id, f_user_id...
>> >   </sql>
>> >
>> >   <select id="selectAction" resultMap="BaseResultMap">
>> >     SELECT <include refid="Base_Column_List" />
>> >     FROM t_action
>> >     WHERE f_order_id = #{orderId}
>> >     AND f_user_id = #{userId}
>> >     ORDER BY f_id DESC LIMIT 1
>> >   </select>
>> >
>> > //Mybatis Interceptor
>> > @Slf4j
>> > @Intercepts({
>> >     @Signature(type = Executor.class, method = "query", args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class, CacheKey.class, BoundSql.class}),
>> >     @Signature(type = Executor.class, method = "query", args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class}),
>> >     @Signature(type = Executor.class, method = "update", args = {MappedStatement.class, Object.class})
>> > })
>> > @Component
>> > public class MyBatisPerfInterceptor implements Interceptor {
>> >   private static final String GLOBAL_METRIC_NAME = "mybatis_mapper_method";
>> >   private static final String GLOBAL_METRIC_NAME_CPUTIME = "mybatis_mapper_method_cputime";
>> >
>> >   private Properties properties;
>> >
>> >   @Autowired
>> >   private StatsdClient statsd;
>> >
>> >   @Override
>> >   public Object intercept(Invocation invocation) throws Throwable {
>> >     String mapperId = "unknownMapperId";
>> >     String className = "unknownClass";
>> >     String methodName = "unknownMethod";
>> >     String sqlType = "unknownType";
>> >
>> >     try {
>> >       MappedStatement mappedStatement = (MappedStatement) invocation.getArgs()[0];
>> >       mapperId = mappedStatement.getId();
>> >       String[] segments = mapperId.split("\\.");
>> >       className = segments[segments.length - 2];
>> >       methodName = segments[segments.length - 1];
>> >       sqlType = mappedStatement.getSqlCommandType().name();
>> >     } catch (Exception e) {
>> >       log.error("failed to capture mybatis method name : {}", mapperId, e);
>> >     }
>> >
>> >     long start = DateUtil.currentTimeMillis();
>> >     Object res = invocation.proceed();
>> >     long end = DateUtil.currentTimeMillis();
>> >
>> >     statsd.histogram(GLOBAL_METRIC_NAME, end - start, "method:" + className + "_" + methodName, "sqlType:" + sqlType);
>> >
>> >     return res;
>> >   }
>> >
>> >
>> >
>> > --
>> > 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" 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 <a href="javascript:" target="_blank" gdf-obfuscated-mailto="75ERlWJ4CgAJ" 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: Query about long latency issue with Mybatis

Iwao AVE!
>  com.zaxxer.hikari.pool.ProxyPreparedStatement:execute took more time than the actual time of SQL?

It is usually the case because of network and data processing in JDBC driver, I think.
In any case, if PreparedStatement#execute() is slow, it has nothing to do with MyBatis (that part is pure JDBC + Hikari CP).

Regards,
Iwao


On Tue, Oct 30, 2018 at 11:17 AM wenxing zheng <[hidden email]> wrote:

Got a call graph from appdynamics for your reference. It seems the com.zaxxer.hikari.pool.ProxyPreparedStatement:execute took more time than the actual time of SQL?



10_13_36__10_30_2018.jpg





On Monday, October 29, 2018 at 10:19:48 PM UTC+8, Iwao AVE! wrote:
It's not metrics, but DEBUG (or TRACE) level logging might give you
more detailed timeline.
With Spring, the following loggers are the relevant ones, IIRC.

- org.springframework.jdbc
- org.mybatis.spring
- com.mycomp.order.repository.OrderMapper (your mapper)

http://www.mybatis.org/mybatis-3/logging.html

// Iwao

On Mon, Oct 29, 2018 at 11:04 AM wenxing zheng <[hidden email]> wrote:

>
> Thanks to Iwao.
>
> I will have a try to reproduce the issue with a small project. But if Mybatis can present the latency metrics for troubleshooting in the future, that would be much better.
>
> On Saturday, October 27, 2018 at 1:03:20 AM UTC+8, Iwao AVE! wrote:
>>
>> Hi Wenxing,
>>
>> The query returns one row and the result map does not have <collection
>> /> nor <association />, so I'm not sure why it's slow.
>>
>> I would suggest you to create a small project with a minimum setup (no
>> spring, no interceptors) as I did in the other thread [1].
>> If it's still slow, upload the project to your repository and I'll
>> take a look when I have some time (you can use different
>> table/column/object names if necessary).
>> If it's fast, add extra stuff like interceptor one by one and you will
>> find the cause eventually.
>>
>> Another option is to use a profiler like VisualVM [2].
>>
>> Regards,
>> Iwao
>>
>> [1] https://groups.google.com/d/msg/mybatis-user/Wubq26QCWYo/GYmXYWS0AgAJ
>> [2] https://visualvm.github.io/
>>
>>
>>
>> On Thu, Oct 25, 2018 at 5:58 PM wenxing zheng <[hidden email]> wrote:
>> >
>> > Thanks to Iwao.
>> >
>> >
>> > Please find the code snippets below for reference.
>> >
>> >
>> >
>> > //Application Logic
>> >
>> >  public void internalSubmitCancel(Long userId, Long orderId) {  Map<String, Object> map = new HashMap<>();
>> >   map.put("orderId", orderId);
>> >   map.put("userId", userId);
>> >   //From the metric stats on Datadog, the selectAction took more than 1s very ofthen. And we didn't find the corresponding slow log on DB server
>> >   //although we set the slow log threshold to 200ms. That's quite puzzled me
>> >   OrderAction orderAction = actionMapper.selectAction(map);
>> >   ...
>> > }
>> >
>> > //BatisMapper
>> > <?xml version="1.0" encoding="UTF-8"?>
>> > <!DOCTYPE mapper PUBLIC "-//mybatis.org//DTD Mapper 3.0//EN" "org/apache/ibatis/builder/xml/mybatis-3-mapper.dtd">
>> > <mapper namespace="com.mycomp.repository.ActionMapper">
>> >   <resultMap id="BaseResultMap" type="com.mycomp.model.OrderAction">
>> >     <id column="f_id" jdbcType="BIGINT" property="id" />
>> >     <result column="f_version" jdbcType="BIGINT" property="version" />
>> >     <result column="f_created_at" jdbcType="BIGINT" property="createdAt" />
>> >     <result column="f_updated_at" jdbcType="BIGINT" property="updatedAt" />
>> >     <result column="f_type" jdbcType="TINYINT" property="type" />
>> >     <result column="f_order_id" jdbcType="BIGINT" property="orderId" />
>> >     <result column="f_user_id" jdbcType="BIGINT" property="userId" />
>> >     ...
>> >   </resultMap>
>> >   <sql id="Base_Column_List">
>> >     f_id, f_version, f_created_at, f_updated_at, f_type, f_order_id, f_user_id...
>> >   </sql>
>> >
>> >   <select id="selectAction" resultMap="BaseResultMap">
>> >     SELECT <include refid="Base_Column_List" />
>> >     FROM t_action
>> >     WHERE f_order_id = #{orderId}
>> >     AND f_user_id = #{userId}
>> >     ORDER BY f_id DESC LIMIT 1
>> >   </select>
>> >
>> > //Mybatis Interceptor
>> > @Slf4j
>> > @Intercepts({
>> >     @Signature(type = Executor.class, method = "query", args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class, CacheKey.class, BoundSql.class}),
>> >     @Signature(type = Executor.class, method = "query", args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class}),
>> >     @Signature(type = Executor.class, method = "update", args = {MappedStatement.class, Object.class})
>> > })
>> > @Component
>> > public class MyBatisPerfInterceptor implements Interceptor {
>> >   private static final String GLOBAL_METRIC_NAME = "mybatis_mapper_method";
>> >   private static final String GLOBAL_METRIC_NAME_CPUTIME = "mybatis_mapper_method_cputime";
>> >
>> >   private Properties properties;
>> >
>> >   @Autowired
>> >   private StatsdClient statsd;
>> >
>> >   @Override
>> >   public Object intercept(Invocation invocation) throws Throwable {
>> >     String mapperId = "unknownMapperId";
>> >     String className = "unknownClass";
>> >     String methodName = "unknownMethod";
>> >     String sqlType = "unknownType";
>> >
>> >     try {
>> >       MappedStatement mappedStatement = (MappedStatement) invocation.getArgs()[0];
>> >       mapperId = mappedStatement.getId();
>> >       String[] segments = mapperId.split("\\.");
>> >       className = segments[segments.length - 2];
>> >       methodName = segments[segments.length - 1];
>> >       sqlType = mappedStatement.getSqlCommandType().name();
>> >     } catch (Exception e) {
>> >       log.error("failed to capture mybatis method name : {}", mapperId, e);
>> >     }
>> >
>> >     long start = DateUtil.currentTimeMillis();
>> >     Object res = invocation.proceed();
>> >     long end = DateUtil.currentTimeMillis();
>> >
>> >     statsd.histogram(GLOBAL_METRIC_NAME, end - start, "method:" + className + "_" + methodName, "sqlType:" + sqlType);
>> >
>> >     return res;
>> >   }
>> >
>> >
>> >
>> > --
>> > 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.

--
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.