如何诊断一个慢任务

用户常常发现一个正在运行或者已经运行结束的任务的运行时间与期望不符。Achelous监控每个任务在整个生命周期内的资源使用情况，这些数据可以帮助回答用户下述问题：

1. 为什么任务这一次运行时间比以前长？
2. 任务运行很久了还没有结束，它还正常吗？
3. 任务运行的资源实际占用是多少？ 下面将详细介绍如何使用这些监控数据回答上述问题。

查看查看作业运行细节

用户通过 biocli job status <job-id> -d 可以找到长时间运行的任务（Task）, 获取必要的任务信息。

[yawei@Cc1Apc simple-error]$ biocli  job status c153f7f5 -d
Status of Job c153f7f5-9be1-43cc-7dc8-e40b996e3ffd:
 Name: simple-job
 Pipeline: SIMPLE-PIPELINE1111
 State: RUNNING
 Owner: yawei
 WorkDir: vol6@xtfs-cluster:yawei/bioflow/wdl/job-simple-job-c153f7f5-9be1-43cc-7dc8-e40b996e3ffd
 PausedState: N/A
 Created: 2021-05-13T15:21:56+08:00
 Finished: N/A
 RetryLimit: 3
 RunCount: 0
 UserStageCount: 0
 StageQuota: -1
 Priority: 9
 FailReason:
 GraphBuildStatus: Completed
 DoneStages: No stage done
 RunningStages: 1
    Stage wk-wk.tool-tool.smoke1:
        Name: stage-smoke1
        Image: gatk3:latest
        State: STAGE_RUNNING
        Output:
        Backend: paladin:paladin-backend.servicemgr.apc:1026
        Task: paladin-task.38d43855-cdfd-4109-af48-7b8fe5619d89
        RetryCount: 0
        Submited: Thu May 13 15:21:57 CST 2021
        Scheduled: Thu May 13 15:23:15 CST 2021
        Finished: N/A
        Duration: N/A
        ExecutionHost: Cc2Apc(172.27.158.6)
        CPU: 2.000000
        Memory: 4000.000000
        Command:        echo "Hello world" > smoke.txt
sleep 100000

1. ExecutionHost: Cc2Apc(172.27.158.6)，说明任务运行的实际物理机器地址。
2. Backend: paladin:paladin-backend.servicemgr.apc:1026，说明任务通过哪一个调度后端提交，普通用户一般不需要关注这个信息。
3. Task: paladin-task.38d43855-cdfd-4109-af48-7b8fe5619d89，指明任务的ID，用于获取资源监控信息。
4. Command：通过获取命令行中比较特殊的标记，例如例子中的特殊文件smoke.txt，可以帮助找到运行的物理机器上的任务对应的进程。

通过资源使用情况判断任务的状态

Achelous 提供了查看任务的资源使用情况的命令biocli job resource 。这个命令既可以获取已经结束的任务的资源使用信息，也可以实时获取正在运行的任务的资源信息。

[yawei@Cc1Apc gatk3-short]$ biocli job resource c153f7f5 paladin-task.38d43855-cdfd-4109-af48-7b8fe5619d89
Resource Usage for job c153f7f5:
 Task stage-smoke1-paladin-task.38d43855-cdfd-4109-af48-7b8fe5619d89 Resource Summary:
   MaxCPURatio: 0.000055
   AvgCPURatio: 0.000028
   LowCPURatio: 1.000000
   TotalCPUTime: 0.020000
   Threads: 1
   MaxMem: 0.085938
   AvgMem: 0.085938
   MaxIOMem: 0.003906
   AvgIOMem: 0.003906
   MaxSwap: 0.000000
   AvgSwap: 0.000000
   TotalRead: 0.000000M
   TotalWrite: 0.003906M
   TotalReadOps: 78.000000
   TotalWriteOps: 5.000000
   MaxProfilingCost: 0.036910
   OutOfMemory: NO
   Period 0 Usage:
    AvgSysRatio: 0.000028
    AvgUserRatio: 0.000028
    MaxMem: 0.085938
    AvgMem: 0.085938
    MaxIOMem: 0.003906
    AvgIOMem: 0.003906
    MaxSwap: 0.000000
    AvgSwap: 0.000000
    TotalRead: 0.000000
    TotalWrite: 0.003906
    TotalReadOps: 78.000000
    TotalWriteOps: 5.000000
   Period 1 Usage:
    AvgSysRatio: 0.000000
    AvgUserRatio: 0.000000
    MaxMem: 0.085938
    AvgMem: 0.085938

如上个例子所示，命令输出了任务在整个运行周期内的资源统计，其中：

1. Summary列出了整个时间的资源使用情况；
2. 后续是每个Period的资源统计，其中每个Period为10分钟。

任何一个任务在执行的过程中，或者占用CPU，或者等待IO，或者通过Swap交换内存数据，或者等待一个事件处于停止运行状态，任意时刻必处在这几种状态的一种或多种。我们根据这个原理做初步判断：

1. 如果Summary中发现任务的AvgCPURatio处于正常状态（CPU占用率的数字的单位为核数，1表示1个核100%，0.3表示一个核的30%），说明任务运行正常。
2. 如果Summary中任务的AvgCPURatio较低，则说明因为等待事件或者IO读写影响了运行效率。则进一步分析Swap和IO情况。如果AvgSwap或者MaxSwap较大，说明任务大量Swap，通常是因为任务的物理内存设置的较小，操作系统在给任务换页浪费了太多时间，则应该调大物理内存申请的数量。如果Swap占用量小，则需要进一步分析是否IO影响了效率或者任务出错。
3. IO情况比较复杂，需要分析每一个Period的TotalRead（总读数据量）和TotalWrite（总写数据量）来判断本周期内是否有大量的IO读写。如果IO读写很小，说明或者IO卡住了，或者任务出现了问题。这个时候需要系统级的诊断。

任务的系统级诊断

如果发现任务占用CPU较小，同时Swap和IO数据量也较小，则需要进行详细的系统级分析：

1. 登陆任务的执行节点，找到任务执行的进程。如上述例子，应该在节点Cc2Apc执行命令ps azjf |grep <smoke.txt> ，就可以获取到当前进程的id。
2. 通过系统命令top可以查看任务的实时信息。
3. 通过iotop可以查看任务的IO等待情况，如果IO或者Swap上的百分比较高，说明花了大量时间等待IO完成，说明是存储或者系统盘性能不够。
4. 通过cat /proc/id/task/*/stack可以查看任务线程的内核Stack，如果发现内核Stack发现大量IO或者Wait，则说明任务被阻塞在了IO或者事件上，应联系系统管理员。

如果仍然无法定位，请联系极道工程师解决。