Why worker take more time to handle task when it's busy? #6675

caishunfeng · 2021-11-03T06:55:01Z

caishunfeng
Nov 3, 2021
Collaborator

When I run 1 master and 1 worker in two machine, run 200 schedule processs for per min.

I found that worker's cpu is high and the echo shell task may take more than 1s to finish, like that:

And I grep the log of the task for id: 1672584 :

[INFO] 2021-11-03 14:24:03.787 org.apache.dolphinscheduler.server.worker.processor.TaskExecuteProcessor:[119] - received command : TaskExecuteRequestCommand{taskExecutionContext='{"taskInstanceId":1672584,"taskName":"task_parent","firstSubmitTime":"2021-11-03 14:24:01","startTime":null,"taskType":"SHELL","host":null,"executePath":null,"logPath":null,"taskJson":null,"processId":0,"processDefineCode":868029953122304,"processDefineVersion":1,"appIds":null,"processInstanceId":1527396,"scheduleTime":"2021-11-03 14:24:00","globalParams":null,"executorId":4,"cmdTypeIfComplement":6,"tenantCode":"root","queue":"queuePythonGateway","projectCode":862677747474432,"taskParams":"{\"rawScript\":\"echo hello pydolphinscheduler\",\"localParams\":[],\"resourceList\":[],\"dependence\":{},\"waitStartTimeout\":{},\"conditionResult\":{\"successNode\":[\"\"],\"failedNode\":[\"\"]}}","envFile":null,"environmentConfig":null,"definedParams":null,"taskAppId":null,"taskTimeoutStrategy":null,"taskTimeout":2147483647,"workerGroup":"default","delayTime":0,"currentExecutionStatus":null,"resources":{},"sqlTaskExecutionContext":{"warningGroupId":0,"connectionParams":null,"udfFuncTenantCodeMap":null,"defaultFS":null},"dataxTaskExecutionContext":{"dataSourceId":0,"sourcetype":0,"sourceConnectionParams":null,"dataTargetId":0,"targetType":0,"targetConnectionParams":null},"dependenceTaskExecutionContext":null,"sqoopTaskExecutionContext":{"dataSourceId":0,"sourcetype":0,"sourceConnectionParams":null,"dataTargetId":0,"targetType":0,"targetConnectionParams":null},"varPool":null,"dryRun":0,"paramsMap":null,"procedureTaskExecutionContext":{"connectionParams":null}}'}
[INFO] 2021-11-03 14:24:03.787 org.apache.dolphinscheduler.server.worker.processor.TaskExecuteProcessor:[142] - task instance local execute path : /tmp/dolphinscheduler/exec/process/862677747474432/868029953122304_1/1527396/1672584
[INFO] 2021-11-03 14:24:03.787 org.apache.dolphinscheduler.common.utils.FileUtils:[145] - create dir success /tmp/dolphinscheduler/exec/process/862677747474432/868029953122304_1/1527396/1672584
[INFO] 2021-11-03 14:24:09.437 org.apache.dolphinscheduler.server.worker.runner.TaskExecuteThread:[137] - script path : /tmp/dolphinscheduler/exec/process/862677747474432/868029953122304_1/1527396/1672584
[INFO] 2021-11-03 14:24:09.437 org.apache.dolphinscheduler.server.worker.runner.TaskExecuteThread:[153] - the task begins to execute. task instance id: 1672584
[INFO] 2021-11-03 14:24:15.997  - [taskAppId=TASK-868029953122304_1-1527396-1672584]:[83] - shell task params {"rawScript":"echo hello pydolphinscheduler","localParams":[],"resourceList":[],"dependence":{},"waitStartTimeout":{},"conditionResult":{"successNode":[""],"failedNode":[""]}}
[INFO] 2021-11-03 14:24:15.997  - [taskAppId=TASK-868029953122304_1-1527396-1672584]:[137] - raw script : echo hello pydolphinscheduler
[INFO] 2021-11-03 14:24:15.997  - [taskAppId=TASK-868029953122304_1-1527396-1672584]:[138] - task execute path : /tmp/dolphinscheduler/exec/process/862677747474432/868029953122304_1/1527396/1672584
[INFO] 2021-11-03 14:24:15.997  - [taskAppId=TASK-868029953122304_1-1527396-1672584]:[86] - tenantCode user:root, task dir:1527396_1672584
[INFO] 2021-11-03 14:24:15.998  - [taskAppId=TASK-868029953122304_1-1527396-1672584]:[91] - create command file:/tmp/dolphinscheduler/exec/process/862677747474432/868029953122304_1/1527396/1672584/1527396_1672584.command
[INFO] 2021-11-03 14:24:15.998  - [taskAppId=TASK-868029953122304_1-1527396-1672584]:[117] - command : #!/bin/sh
/tmp/dolphinscheduler/exec/process/862677747474432/868029953122304_1/1527396/1672584/1527396_1672584_node.sh
[INFO] 2021-11-03 14:24:16.009  - [taskAppId=TASK-868029953122304_1-1527396-1672584]:[285] - task run command: sudo -u root sh /tmp/dolphinscheduler/exec/process/862677747474432/868029953122304_1/1527396/1672584/1527396_1672584.command
[INFO] 2021-11-03 14:24:16.654  - [taskAppId=TASK-868029953122304_1-1527396-1672584]:[176] - process start, process id is: 792401
[INFO] 2021-11-03 14:24:16.654  - [taskAppId=TASK-868029953122304_1-1527396-1672584]:[200] - process has exited, execute path:/tmp/dolphinscheduler/exec/process/862677747474432/868029953122304_1/1527396/1672584, processId:792401 ,exitStatusCode:0 ,processWaitForStatus:true ,processExitValue:0
[INFO] 2021-11-03 14:24:16.654 org.apache.dolphinscheduler.server.worker.runner.TaskExecuteThread:[207] - task instance id : 1672584,task final status : SUCCESS
[INFO] 2021-11-03 14:24:16.654 org.apache.dolphinscheduler.server.worker.runner.TaskExecuteThread:[250] - exec local path: /tmp/dolphinscheduler/exec/process/862677747474432/868029953122304_1/1527396/1672584 cleared.
[INFO] 2021-11-03 14:24:17.688  - [taskAppId=TASK-868029953122304_1-1527396-1672584]:[61] -  -> welcome to use bigdata scheduling system...
[INFO] 2021-11-03 14:24:17.688  - [taskAppId=TASK-868029953122304_1-1527396-1672584]:[55] - FINALIZE_SESSION

caishunfeng · 2021-11-03T07:02:34Z

caishunfeng
Nov 3, 2021
Collaborator Author

I found that two point about the log:

Between create dir success and script path, it tasks about 6s.
Between the task begins to execute and shell task params, it tasks about 6s;

0 replies

caishunfeng · 2021-11-03T08:54:50Z

caishunfeng
Nov 3, 2021
Collaborator Author

`---ts=2021-11-03 16:51:46;thread_name=Worker-Execute-Thread;id=ce;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@5c647e05
    `---[4302.854744ms] org.apache.dolphinscheduler.server.worker.runner.TaskExecuteThread:run()
        +---[0.001665ms] org.apache.dolphinscheduler.service.queue.entity.TaskExecutionContext:getTaskInstanceId() #135
        +---[0.001241ms] org.apache.dolphinscheduler.service.queue.entity.TaskExecutionContext:getProcessInstanceId() #135
        +---[0.001255ms] org.apache.dolphinscheduler.remote.command.TaskExecuteResponseCommand:<init>() #135
        +---[0.001241ms] org.apache.dolphinscheduler.service.queue.entity.TaskExecutionContext:getExecutePath() #137
        +---[0.072919ms] org.slf4j.Logger:info() #137
        +---[0.054009ms] org.apache.dolphinscheduler.common.utils.OSUtils:getUserList() #139
        +---[0.001467ms] org.apache.dolphinscheduler.service.queue.entity.TaskExecutionContext:getTenantCode() #139
        +---[0.001277ms] org.apache.dolphinscheduler.service.queue.entity.TaskExecutionContext:getStartTime() #147
        +---[0.001459ms] org.apache.dolphinscheduler.service.queue.entity.TaskExecutionContext:getCurrentExecutionStatus() #150
        +---[0.00109ms] org.apache.dolphinscheduler.service.queue.entity.TaskExecutionContext:getTaskInstanceId() #153
        +---[0.048331ms] org.slf4j.Logger:info() #153
        +---[0.001491ms] org.apache.dolphinscheduler.service.queue.entity.TaskExecutionContext:getDryRun() #155
        +---[0.001095ms] org.apache.dolphinscheduler.service.queue.entity.TaskExecutionContext:getExecutePath() #158
        +---[0.001248ms] org.apache.dolphinscheduler.service.queue.entity.TaskExecutionContext:getResources() #159
        +---[0.002141ms] org.apache.dolphinscheduler.server.worker.runner.TaskExecuteThread:downloadResource() #158
        +---[0.025994ms] org.apache.dolphinscheduler.common.utils.CommonUtils:getSystemEnvPath() #163
        +---[0.00142ms] org.apache.dolphinscheduler.service.queue.entity.TaskExecutionContext:setEnvFile() #163
        +---[0.002709ms] org.apache.dolphinscheduler.server.worker.runner.TaskExecuteThread:getGlobalParamsMap() #164
        +---[0.001175ms] org.apache.dolphinscheduler.service.queue.entity.TaskExecutionContext:setDefinedParams() #164
        +---[0.001128ms] org.apache.dolphinscheduler.service.queue.entity.TaskExecutionContext:getProcessInstanceId() #167
        +---[9.78E-4ms] org.apache.dolphinscheduler.service.queue.entity.TaskExecutionContext:getTaskInstanceId() #168
        +---[0.001506ms] org.apache.dolphinscheduler.service.queue.entity.TaskExecutionContext:setTaskAppId() #166
        +---[0.011279ms] org.apache.dolphinscheduler.server.worker.runner.TaskExecuteThread:preBuildBusinessParams() #170
        +---[0.001506ms] org.apache.dolphinscheduler.server.worker.plugin.TaskPluginManager:getTaskChannelMap() #172
        +---[0.001204ms] org.apache.dolphinscheduler.service.queue.entity.TaskExecutionContext:getTaskType() #172
        +---[0.055287ms] org.apache.dolphinscheduler.common.utils.JSONUtils:toJsonString() #176
        +---[0.080781ms] org.apache.dolphinscheduler.common.utils.JSONUtils:parseObject() #176
        +---[0.001384ms] org.apache.dolphinscheduler.service.queue.entity.TaskExecutionContext:getProcessDefineCode() #178
        +---[0.001338ms] org.apache.dolphinscheduler.service.queue.entity.TaskExecutionContext:getProcessDefineVersion() #179
        +---[0.001071ms] org.apache.dolphinscheduler.service.queue.entity.TaskExecutionContext:getProcessInstanceId() #180
        +---[0.001031ms] org.apache.dolphinscheduler.service.queue.entity.TaskExecutionContext:getTaskInstanceId() #181
        +---[0.008284ms] org.apache.dolphinscheduler.common.utils.LoggerUtils:buildTaskId() #177
        +---[0.001276ms] org.apache.dolphinscheduler.spi.task.request.TaskRequest:setTaskLogName() #182
        +---[4113.605928ms] org.apache.dolphinscheduler.spi.task.TaskChannel:createTask() #184
        +---[0.500354ms] org.apache.dolphinscheduler.spi.task.AbstractTask:init() #186
        +---[0.001598ms] org.apache.dolphinscheduler.spi.task.AbstractTask:getParameters() #188
        +---[0.001517ms] org.apache.dolphinscheduler.service.queue.entity.TaskExecutionContext:getVarPool() #188
        +---[0.001327ms] org.apache.dolphinscheduler.spi.task.AbstractParameters:setVarPool() #188
        +---[187.870361ms] org.apache.dolphinscheduler.spi.task.AbstractTask:handle() #192
        +---[0.001852ms] org.apache.dolphinscheduler.spi.task.AbstractTask:getNeedAlert() #195
        +---[0.001598ms] org.apache.dolphinscheduler.spi.task.AbstractTask:getExitStatus() #198
        +---[0.001668ms] org.apache.dolphinscheduler.spi.task.ExecutionStatus:getCode() #198
        +---[0.00172ms] org.apache.dolphinscheduler.remote.command.TaskExecuteResponseCommand:setStatus() #198
        +---[0.001483ms] org.apache.dolphinscheduler.remote.command.TaskExecuteResponseCommand:setEndTime() #203
        +---[0.00121ms] org.apache.dolphinscheduler.spi.task.AbstractTask:getProcessId() #204
        +---[0.001336ms] org.apache.dolphinscheduler.remote.command.TaskExecuteResponseCommand:setProcessId() #204
        +---[0.001066ms] org.apache.dolphinscheduler.spi.task.AbstractTask:getAppIds() #205
        +---[0.001207ms] org.apache.dolphinscheduler.remote.command.TaskExecuteResponseCommand:setAppIds() #205
        +---[0.001347ms] org.apache.dolphinscheduler.spi.task.AbstractTask:getParameters() #206
        +---[0.001364ms] org.apache.dolphinscheduler.spi.task.AbstractParameters:getVarPool() #206
        +---[0.003633ms] org.apache.dolphinscheduler.common.utils.JSONUtils:toJsonString() #206
        +---[0.001235ms] org.apache.dolphinscheduler.remote.command.TaskExecuteResponseCommand:setVarPool() #206
        +---[0.001733ms] org.apache.dolphinscheduler.service.queue.entity.TaskExecutionContext:getTaskInstanceId() #207
        +---[0.001176ms] org.apache.dolphinscheduler.spi.task.AbstractTask:getExitStatus() #207
        +---[0.049561ms] org.slf4j.Logger:info() #207
        +---[0.001323ms] org.apache.dolphinscheduler.service.queue.entity.TaskExecutionContext:getTaskInstanceId() #217
        +---[0.002491ms] org.apache.dolphinscheduler.spi.task.TaskExecutionContextCacheManager:removeByTaskInstanceId() #217
        +---[0.001427ms] org.apache.dolphinscheduler.server.worker.cache.ResponceCache:get() #218
        +---[0.001023ms] org.apache.dolphinscheduler.service.queue.entity.TaskExecutionContext:getTaskInstanceId() #218
        +---[0.011915ms] org.apache.dolphinscheduler.remote.command.TaskExecuteResponseCommand:convert2Command() #218
        +---[0.002097ms] org.apache.dolphinscheduler.server.worker.cache.ResponceCache:cache() #218
        +---[0.001043ms] org.apache.dolphinscheduler.service.queue.entity.TaskExecutionContext:getTaskInstanceId() #219
        +---[0.003637ms] org.apache.dolphinscheduler.remote.command.TaskExecuteResponseCommand:convert2Command() #219
        +---[0.012059ms] org.apache.dolphinscheduler.server.worker.processor.TaskCallbackService:sendResult() #219
        `---[0.248569ms] org.apache.dolphinscheduler.server.worker.runner.TaskExecuteThread:clearTaskExecPath() #220

I use arthas to trace org.apache.dolphinscheduler.server.worker.runner.TaskExecuteThread run, and found that
+---[4113.605928ms] org.apache.dolphinscheduler.spi.task.TaskChannel:createTask() #184 takes many time.

1 reply

caishunfeng Nov 3, 2021
Collaborator Author

`---ts=2021-11-03 17:34:13;thread_name=Worker-Execute-Thread;id=bf;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@5c647e05
    `---[1334.780629ms] ch.qos.logback.classic.LoggerContext:getLogger()
        `---[1334.776113ms] ch.qos.logback.classic.LoggerContext:getLogger() #53
            `---[1334.771275ms] ch.qos.logback.classic.LoggerContext:getLogger()
                +---[0.001771ms] ch.qos.logback.classic.util.LoggerNameUtil:getSeparatorIndexOf() #143
                +---[37.044229ms] ch.qos.logback.classic.Logger:getChildByName() #152
                +---[0.511034ms] ch.qos.logback.classic.Logger:createChildByName() #154
                `---[0.002619ms] ch.qos.logback.classic.LoggerContext:incSize() #156

I found the synchronized for Logger[Root] will take more than 1s sometimes.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Why worker take more time to handle task when it's busy? #6675

{{title}}

{{editor}}'s edit

{{editor}}'s edit

Replies: 2 comments 1 reply

{{title}}

{{title}}

{{title}}

Select a reply

Why worker take more time to handle task when it's busy? #6675

caishunfeng Nov 3, 2021 Collaborator

Replies: 2 comments · 1 reply

caishunfeng Nov 3, 2021 Collaborator Author

caishunfeng Nov 3, 2021 Collaborator Author

caishunfeng Nov 3, 2021 Collaborator Author

caishunfeng
Nov 3, 2021
Collaborator

Replies: 2 comments 1 reply

caishunfeng
Nov 3, 2021
Collaborator Author

caishunfeng
Nov 3, 2021
Collaborator Author

caishunfeng Nov 3, 2021
Collaborator Author