dolphinscheduler3.0.0任务日志中打N遍sql的问题

yangls的技术博客

已于 2023-06-14 17:27:28 修改

阅读量1k

点赞数

文章标签：大数据

于 2021-03-27 16:52:38 首次发布

本文链接：https://blog.csdn.net/weixin_44597427/article/details/115267691

版权

大数据优秀开源项目源码拆解专栏收录该内容

6 篇文章 0 订阅

订阅专栏

遇见问题：我们在查看dolphinscheduler任务日志的时候发现会打N遍日志，特别是在我们sql中参数比较多的时候，最严重有一次打了十几次，非常影响我们排错体验，特别是sql比较长的时候。

[LOG-PATH]: /opt/dolphinscheduler/logs/20230208/8169387546080_23-4654-2022.log, [HOST]:  Host{address='dolphinscheduler-worker-0.dolphinscheduler-worker-headless:1234', ip='dolphinscheduler-worker-0.dolphinscheduler-worker-headless', port=1234}
[INFO] 2023-02-08 05:01:05.720 +0800 [taskAppId=TASK-20230208-8169387546080_23-4654-2022] TaskLogLogger-class org.apache.dolphinscheduler.plugin.task.sql.SqlTask:[120] - Full sql parameters: SqlParameters{type='CLICKHOUSE', datasource=2, sql='alte
INSERT INTO bigdata_bi.t_report_manager_customer_preference_1d SELECT fcorp_id, manager_id, fdept_type, content_type, tag_name, cnts, toDate(${fdate}), date_sub(SECOND,1,date_add(day,1,toDate(${fdate}))), date_sub(SECOND,1,date_add(day,1,toDate(${
[INFO] 2023-02-08 05:01:05.721 +0800 [taskAppId=TASK-20230208-8169387546080_23-4654-2022] TaskLogLogger-class org.apache.dolphinscheduler.plugin.task.sql.SqlTask:[121] - sql type : CLICKHOUSE, datasource : 2, sql : alter table bigdata_bi.t_report_
INSERT INTO bigdata_bi.t_report_manager_customer_preference_1d SELECT fcorp_id, manager_id, fdept_type, content_type, tag_name, cnts, toDate(${fdate}), date_sub(SECOND,1,date_add(day,1,toDate(${fdate}))), date_sub(SECOND,1,date_add(day,1,toDate(${
[INFO] 2023-02-08 05:01:05.721 +0800 [taskAppId=TASK-20230208-8169387546080_23-4654-2022] TaskLogLogger-class org.apache.dolphinscheduler.plugin.task.sql.SqlTask:[91] - setSqlParamsMap: Property with paramName: fdate put in sqlParamsMap of content
alter table bigdata_bi.t_report_manager_customer_preference_1d_local on CLUSTER 'clickhouse' drop partition ("'"${fdate}"'"); successfully.
[INFO] 2023-02-08 05:01:05.722 +0800 [taskAppId=TASK-20230208-8169387546080_23-4654-2022] TaskLogLogger-class org.apache.dolphinscheduler.plugin.task.sql.SqlTask:[385] - after replace sql , preparing : 
alter table bigdata_bi.t_report_manager_customer_preference_1d_local on CLUSTER 'clickhouse' drop partition (?);
[INFO] 2023-02-08 05:01:05.722 +0800 [taskAppId=TASK-20230208-8169387546080_23-4654-2022] TaskLogLogger-class org.apache.dolphinscheduler.plugin.task.sql.SqlTask:[394] - Sql Params are replaced sql , parameters:2023-02-07(VARCHAR)
[INFO] 2023-02-08 05:01:05.722 +0800 [taskAppId=TASK-20230208-8169387546080_23-4654-2022] TaskLogLogger-class org.apache.dolphinscheduler.plugin.task.sql.SqlTask:[91] - setSqlParamsMap: Property with paramName: fdate put in sqlParamsMap of content
INSERT INTO bigdata_bi.t_report_manager_customer_preference_1d SELECT fcorp_id, manager_id, fdept_type, content_type, tag_name, cnts, toDate(${fdate}), date_sub(SECOND,1,date_add(day,1,toDate(${fdate}))), date_sub(SECOND,1,date_add(day,1,toDate(${
[INFO] 2023-02-08 05:01:05.722 +0800 [taskAppId=TASK-20230208-8169387546080_23-4654-2022] TaskLogLogger-class org.apache.dolphinscheduler.plugin.task.sql.SqlTask:[91] - setSqlParamsMap: Property with paramName: fdate put in sqlParamsMap of content
INSERT INTO bigdata_bi.t_report_manager_customer_preference_1d SELECT fcorp_id, manager_id, fdept_type, content_type, tag_name, cnts, toDate(${fdate}), date_sub(SECOND,1,date_add(day,1,toDate(${fdate}))), date_sub(SECOND,1,date_add(day,1,toDate(${
[INFO] 2023-02-08 05:01:05.722 +0800 [taskAppId=TASK-20230208-8169387546080_23-4654-2022] TaskLogLogger-class org.apache.dolphinscheduler.plugin.task.sql.SqlTask:[91] - setSqlParamsMap: Property with paramName: fdate put in sqlParamsMap of content
INSERT INTO bigdata_bi.t_report_manager_customer_preference_1d SELECT fcorp_id, manager_id, fdept_type, content_type, tag_name, cnts, toDate(${fdate}), date_sub(SECOND,1,date_add(day,1,toDate(${fdate}))), date_sub(SECOND,1,date_add(day,1,toDate(${
[INFO] 2023-02-08 05:01:05.722 +0800 [taskAppId=TASK-20230208-8169387546080_23-4654-2022] TaskLogLogger-class org.apache.dolphinscheduler.plugin.task.sql.SqlTask:[91] - setSqlParamsMap: Property with paramName: fdate put in sqlParamsMap of content

那究竟是什么原因呢？让我们进入源码一探究竟：

首先日志很清晰告诉我们是在这个类中打的：org.apache.dolphinscheduler.plugin.task.sql.SqlTask
最多的91行，这个其实是在他的父类中：AbstractTaskExecutor
有如下代码段：

public void setSqlParamsMap(String content, String rgex, Map<Integer, Property> sqlParamsMap,
                                Map<String, Property> paramsPropsMap,int taskInstanceId) {
        Pattern pattern = Pattern.compile(rgex);
        Matcher m = pattern.matcher(content);
        int index = 1;
        while (m.find()) {

            String paramName = m.group(1);
            Property prop = paramsPropsMap.get(paramName);

            if (prop == null) {
                logger.error("setSqlParamsMap: No Property with paramName: {} is found in paramsPropsMap of task instance"
                    + " with id: {}. So couldn't put Property in sqlParamsMap.", paramName, taskInstanceId);
            } else {
                sqlParamsMap.put(index, prop);
                index++;
                logger.info("setSqlParamsMap: Property with paramName: {} put in sqlParamsMap of content {} successfully.", paramName, content);
            }

        }
    }

可以看出这是在设置参数，每设置一个参数就打一次原sql……我看原来sql中有9个参数，所以将sql打印了9次……再看看这个方法在哪里调用的呢？

private SqlBinds getSqlAndSqlParamsMap(String sql) {
        Map<Integer, Property> sqlParamsMap = new HashMap<>();
        StringBuilder sqlBuilder = new StringBuilder();

        // combining local and global parameters
        Map<String, Property> paramsMap = ParamUtils.convert(taskExecutionContext, getParameters());

        // spell SQL according to the final user-defined variable
        if (paramsMap == null) {
            sqlBuilder.append(sql);
            return new SqlBinds(sqlBuilder.toString(), sqlParamsMap);
        }

        if (StringUtils.isNotEmpty(sqlParameters.getTitle())) {
            String title = ParameterUtils.convertParameterPlaceholders(sqlParameters.getTitle(),
                    ParamUtils.convert(paramsMap));
            logger.info("SQL title : {}", title);
            sqlParameters.setTitle(title);
        }

        //new
        //replace variable TIME with $[YYYYmmddd...] in sql when history run job and batch complement job
        sql = ParameterUtils.replaceScheduleTime(sql, taskExecutionContext.getScheduleTime());
        // special characters need to be escaped, ${} needs to be escaped
        setSqlParamsMap(sql, rgex, sqlParamsMap, paramsMap,taskExecutionContext.getTaskInstanceId());
        //Replace the original value in sql ！{...} ，Does not participate in precompilation
        String rgexo = "['\"]*\\!\\{(.*?)\\}['\"]*";
        sql = replaceOriginalValue(sql, rgexo, paramsMap);
        // replace the ${} of the SQL statement with the Placeholder
        String formatSql = sql.replaceAll(rgex, "?");
        sqlBuilder.append(formatSql);

        // print repalce sql
        printReplacedSql(sql, formatSql, rgex, sqlParamsMap);
        return new SqlBinds(sqlBuilder.toString(), sqlParamsMap);
    }

可见上面每个参数都打印一次其实毫无比较，加上上下文中一个打了十几次，程序运行到这里前面肯定已经将原sql打印过了，所以这里其实只要打印参数就行，日志会精简很多，特别是在sql很长的时候。

找到问题就好说了，修改代码重新编译打包部署api模块到k8s就解决了