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

Uh oh!

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

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Replies: 2 comments 1 reply

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Select a reply

Uh oh!

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

Uh oh!

Uh oh!

caishunfeng Nov 3, 2021 Collaborator

Replies: 2 comments · 1 reply

Uh oh!

caishunfeng Nov 3, 2021 Collaborator Author

Uh oh!

caishunfeng Nov 3, 2021 Collaborator Author

Uh oh!

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