Mybatis-3: Feature Request: Add SQL Comment globally for distributed tracing

[wreulicke]

Hi.
I would like to add SQL comment like below globally to all SQL.

SELECT * FROM users; /* TraceID: foo-bar-baz */

So, I wrote this code.
But, This uses reflection API.
Therefore, this code is not production-ready.

Is there another way?
I need a way to enable to add SQL comment generated by some code.

Motivation

SQL with TraceID is useful.
If we just find a query without TraceID in slow query log, we cannot identify a transaction.
But, if there are TraceID in slow query, we can trace a transaction.

So I need.

[qixiaobo]

This comment generate for every request? So it may inject by some framework like skywalking?

[qixiaobo]

TraceId is different for every request even the sql is the same~ So I dont think it's easy to do.
How about prepared statement？

[wreulicke]

This comment generate for every request?

yes.

So it may inject by some framework like skywalking?

I'm not sure, TraceID is injected by some tracing library,
but I think the comment is not injected by the library.

[wreulicke]

So I dont think it's easy to do.
How about prepared statement？

fmm... I agree with you.

In this case, PreparedStatement is generated for every request.
I think this will causes performance degradation.
So, we can not ignore this degradation...

[tokuhirom]

MySQL users aren't using server side prepared statement(It's totally broken). As a result, MySQL users can ignore the overhead.

[kazuki43zoo]

Is there another way?

FYI:
As technically, it can be realized by the following way. But I'm not sure this way is good solution.

This way is appending OGNL expression to all queries using LanguageDriver feature as follow:

public class TraceIdPropagatingLanguageDriver implements LanguageDriver {

    private static final String TRACE_ID_COMMENT = " /* TraceID:${@org.slf4j.MDC@get('requestId')} */";

    private final LanguageDriver delegate;

    public RequestIdPropagatingLanguageDriver(LanguageDriver delegate) {
        this.delegate = delegate;
    }

    @Override
    public ParameterHandler createParameterHandler(MappedStatement mappedStatement, Object parameterObject, BoundSql boundSql) {
        return delegate.createParameterHandler(mappedStatement, parameterObject, boundSql);
    }

    @Override
    public SqlSource createSqlSource(Configuration configuration, XNode script, Class<?> parameterType) {
        script.getNode().appendChild(script.getNode().getOwnerDocument().createTextNode(TRACE_ID_COMMENT));
        return delegate.createSqlSource(configuration, script, parameterType);
    }

    @Override
    public SqlSource createSqlSource(Configuration configuration, String script, Class<?> parameterType) {
        String targetScript = script;
        if (script.startsWith("<script>")) {
            int index = script.lastIndexOf("</script>");
            if (index != -1) {
                targetScript = script.substring(0, index) + TRACE_ID_COMMENT + script.substring(index);
            }
        }
        else {
            targetScript = script + TRACE_ID_COMMENT;
        }
        return delegate.createSqlSource(configuration, targetScript, parameterType);
    }
}

@Bean
LanguageDriver traceIdPropagatingLanguageDriver() {
    return new TraceIdPropagatingLanguageDriver(new XMLLanguageDriver());
}

Mapper:

@Mapper
public interface MyMapper {
    @Select("select 1")
    int ping();
}

Result:

@Test
void contextLoads(@Autowired MyMapper mapper) {
    MDC.put("requestId", UUID.randomUUID().toString());
    System.out.println(mapper.ping());
    MDC.put("requestId", UUID.randomUUID().toString());
    System.out.println(mapper.ping());
}

2019-12-13 01:31:11.282 DEBUG 63551 --- [           main] com.example.mybatisgh1778.MyMapper.ping  : ==>  Preparing: select 1 /* TraceID:bbcc99ff-4e7a-42d5-acd0-b24e18a9f48b */ 
2019-12-13 01:31:11.306 DEBUG 63551 --- [           main] com.example.mybatisgh1778.MyMapper.ping  : ==> Parameters: 
2019-12-13 01:31:11.322 TRACE 63551 --- [           main] com.example.mybatisgh1778.MyMapper.ping  : <==    Columns: 1
2019-12-13 01:31:11.322 TRACE 63551 --- [           main] com.example.mybatisgh1778.MyMapper.ping  : <==        Row: 1
2019-12-13 01:31:11.325 DEBUG 63551 --- [           main] com.example.mybatisgh1778.MyMapper.ping  : <==      Total: 1
1
2019-12-13 01:31:11.332 DEBUG 63551 --- [           main] com.example.mybatisgh1778.MyMapper.ping  : ==>  Preparing: select 1 /* TraceID:27d56d8b-1d4c-473c-aac1-b464df7e9b9b */ 
2019-12-13 01:31:11.333 DEBUG 63551 --- [           main] com.example.mybatisgh1778.MyMapper.ping  : ==> Parameters: 
2019-12-13 01:31:11.333 TRACE 63551 --- [           main] com.example.mybatisgh1778.MyMapper.ping  : <==    Columns: 1
2019-12-13 01:31:11.333 TRACE 63551 --- [           main] com.example.mybatisgh1778.MyMapper.ping  : <==        Row: 1
2019-12-13 01:31:11.333 DEBUG 63551 --- [           main] com.example.mybatisgh1778.MyMapper.ping  : <==      Total: 1
1

[qixiaobo]

Good idea~

[qixiaobo]

But I still concern about this trick. Just because our trace systems may store some
sql in its structs. We use traceId for some profile with our system like microSystems.
But you never can use this traceId to profile your sql. We may get infos like 'select * from * where * 100ms' .This may help we profile our sql. We only need to know this above.