一个100%CPU占用率，但是线程名混乱和top不准问题定位过程

关键词：task_newtask、task_rename、process tree、top等。

有一个场景CPU占用率100%，同时进程下创建了一大堆线程，很多线程同样的名称。

而且存在一个情况，top查看所有进程占用率要远小于100%。

这里有两个问题，一是线程同名问题，由于程序设计之初没有考虑线程名问题，导致无法根据把线程名和业务联系起来；而且通过top/pstree能看到的这是进程和线程的父子关系。

二是，这些丢失的CPU占用率究竟哪里去了？

 

1. 获取进程下所有线程的树形结构

这一步很关键，因为很多系统中线程的创建非常频繁，而且处理完任务，快速退出。

常用的工具top和pstree等，对线程之间的父子关系是没有显示的，只明确了进程和线程的父子关系。

这里借助/sys/kernel/debug/tracing/events/task/下的task_newtask和task_rename，这两者分别创建线程，然后对线程改名。

有了这两个trace events，就可以记录新创建的线程，新创建的线程和父线程同名，然后通过task_rename进行名称修改，常用的是prctl()。

1.1 抓取task_newtask和task_rename数据

通过trace event抓取到的数据如下，task_newtask详细记录了线程由谁创建(父线程)、创建了谁(子线程)、名称是什么(子线程名)，然后task_rename详细记录了哪个线程由什么旧名称改成了什么新名称。

              sh-153   [000] ....    53.734695: task_newtask: pid=165 comm=sh clone_flags=1200011 oom_score_adj=0
             cat-165   [000] ...1    53.738804: task_rename: pid=165 oldcomm=sh newcomm=cat oom_score_adj=0
              sh-153   [000] ....    84.638270: task_newtask: pid=166 comm=sh clone_flags=1200011 oom_score_adj=0
   xchip_runtime-166   [000] ...1    84.645910: task_rename: pid=166 oldcomm=sh newcomm=xchip_runtime oom_score_adj=0
   xchip_runtime-166   [000] ....    85.098260: task_newtask: pid=167 comm=xchip_runtime clone_flags=3d0f00 oom_score_adj=0
   Log2Hostflush-167   [000] ...1    85.099145: task_rename: pid=167 oldcomm=xchip_runtime newcomm=Log2Hostflush oom_score_adj=0
   xchip_runtime-166   [000] ....    85.133881: task_newtask: pid=168 comm=xchip_runtime clone_flags=3d0f00 oom_score_adj=0
 usb_server_list-168   [000] ...1    85.134077: task_rename: pid=168 oldcomm=xchip_runtime newcomm=usb_server_list oom_score_adj=0
 usb_server_list-168   [000] ....   116.497292: task_newtask: pid=169 comm=usb_server_list clone_flags=3d0f00 oom_score_adj=0
        coreComm-169   [000] ...1   116.501998: task_rename: pid=169 oldcomm=usb_server_list newcomm=coreComm oom_score_adj=0
 usb_server_list-168   [000] ....   116.514232: task_newtask: pid=170 comm=usb_server_list clone_flags=3d0f00 oom_score_adj=0

1.2 脚本分析生成线程树形结构

在jupyter-notebook中读取trace.txt文件，然后从中提取关键信息，pid、comm、父pid、子pid列表。

以pid为字典键值，分析过程如下。

import re

process_tree = {}
ap_trace_file = open('/home/al/trace.txt', 'rb')
for line in ap_trace_file:
    ftrace_line_fmt = \
        ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\[(?P<cpu>[0-9]*)\] *'+\
        '(?P<flags>.{4}) *(?P<ktime>[0-9\.]*): *'+\
        '(?P<msg>.*)'
    m = re.match(ftrace_line_fmt, line)
    if(not m):
        continue
    proc = m.group('proc')
    pid = m.group('pid')
    msg = m.group('msg')
    if (not process_tree.has_key(pid)):
        process_tree[pid] = {'comm':proc, 'child':[], 'father':0}

    #Analyze task_newtask.
    #task_newtask: pid=165 comm=sh clone_flags=1200011 oom_score_adj=0
    task_newtask_fmt = 'task_newtask: pid=(?P<cpid>[0-9]*) comm=(?P<comm>.*) clone_flags.*'
    m = re.match(task_newtask_fmt, msg)
    if(m):
        cpid = m.group('cpid')
        comm = m.group('comm')
        #print pid, cpid, comm
        #process_tree.update({cpid:{'child':[], 'comm':comm}})
        process_tree[pid]['child'].append(cpid)
        if(not process_tree.has_key(cpid)):
            process_tree[cpid] = {'comm':comm, 'child':[], 'father':pid}

    #Analyze task_rename.
    #task_rename: pid=170 oldcomm=usb_server_list newcomm=adapter oom_score_adj=0
    task_rename_fmt = 'task_rename: pid=(?P<cpid>[0-9]*) oldcomm=(?P<oldcomm>.*) newcomm=(?P<newcomm>.*) oom_score_adj.*'
    m = re.match(task_rename_fmt, msg)
    if(m):
        cpid = m.group('cpid')
        oldcomm = m.group('oldcomm')
        newcomm = m.group('newcomm')
        process_tree[cpid]['comm'] = newcomm
        #print cpid, oldcomm, newcomm
ap_trace_file.close()

然后根据process_tree解析结果，显示成树形结构：

for key, item in process_tree.items():
    if ( item['father'] == 0 ):
        print item['comm']+':'+key
        for child1 in item['child']:
            print "    |-2-"+process_tree[child1]['comm']+':'+child1
            for child2 in process_tree[child1]['child']:
                print "        |-3-"+process_tree[child2]['comm']+':'+child2
                for child3 in process_tree[child2]['child']:
                    print "            |-4-"+process_tree[child3]['comm']+':'+child3
                    for child4 in process_tree[child3]['child']:
                        print "                |-5-"+process_tree[child4]['comm']+':'+child4
                        for child5 in process_tree[child4]['child']:
                            print "                    |-6-"+process_tree[child5]['comm']+':'+child5
                            for child6 in process_tree[child5]['child']:
                                print "                        |-7-"+process_tree[child6]['comm']+':'+child6
                                for child7 in process_tree[child6]['child']:
                                    print "                            |-8-"+process_tree[child7]['comm']+':'+child7

最终输出结果如下。

这里可以看出xchip_runtime下所有线程的创建轨迹，以及其父子关系。

sh:153
    |-2-cat:165
    |-2-xchip_runtime:166
        |-3-Log2Hostflush:167
        |-3-usb_server_list:168
            |-4-coreComm:169
            |-4-adapter:170
            |-4-usb_server_list:171
            |-4-sh:172
                |-5-fp_download_tes:173
                    |-6-sh:174
                        |-7-find:175
                        |-7-awk:176
                    |-6-sh:177
                        |-7-rm:178
            |-4-usb_server_list:179
                |-5-usb_server_list:202
                |-5-usb_server_list:203
...
                |-5-usb_server_list:2851
                |-5-usb_server_list:2852
            |-4-usb_server_list:180
            |-4-p2p_rx_task:181
            |-4-IFMS_Init:182
            |-4-omx_main:183
                |-5-omx_g1_output:218
            |-4-src:src:184
                |-5-omxdec:src:219
            |-4-iccsrc_rx:185
            |-4-usb_server_list:186
            |-4-p2p_rx_task:187
            |-4-omx_main:188
                |-5-omx_g1_output:192
            |-4-src:src:189
                |-5-omxdec:src:193
            |-4-iccsrc_rx:190
            |-4-usb_server_list:191
            |-4-p2p_rx_task:194
            |-4-omx_main:195
                |-5-omx_g1_output:199
            |-4-src:src:196
                |-5-omxdec:src:200
            |-4-iccsrc_rx:197
            |-4-usb_server_list:198
            |-4-p2p_rx_task:201
            |-4-omx_main:228
                |-5-omx_g1_output:240
            |-4-src:src:229
                |-5-omxdec:src:241
            |-4-iccsrc_rx:230
            |-4-usb_server_list:235
    |-2-top:646
    |-2-pidof:1873
    |-2-top:1907
    |-2-cat:2830

2. 单线程or多线程执行

根据usb_server_list:179线程的创建线程数量和频率，结合功能就可以判定其对应关系。

线程占用率低于100%的原因，可能是由于usb_server_list创建的子线程频繁创建并快速退出。

在top采样周期内并不能完成的存在，这些线程所占用的CPU资源，在总和中得到了统计，但是在top显示具体进程/线程的时候无法统计到。

为了验证构造两个不同的应用，启动一个周期性timer，频率可调整。

然后一个应用顺序执行四个任务，另一个应用分别启动四个线程执行四个任务。

通过top查看其CPU占用率。

2.1 测试程序

创建四个线程分别执行任务： 

#include <pthread.h>
#include <unistd.h>
#include <thread>
#include <stdio.h>
#include <time.h>
#include <stdlib.h>
#include <signal.h>
#include <string.h>

unsigned int count = 0;
#define LOOP_COUNT 40000

void thread_fn(void)
{
    unsigned int i, a;
    for(i = 0; i < LOOP_COUNT; i++) {
        a++;
    }
}

void timer_thread(union sigval v)
{
    std::thread thread1, thread2, thread3, thread4;

    //printf("pthread count=%d.\n", count++);

    thread1 = std::thread(thread_fn);
    thread2 = std::thread(thread_fn);
    thread3 = std::thread(thread_fn);
    thread4 = std::thread(thread_fn);

    thread1.join();
    thread2.join();
    thread3.join();
    thread4.join();
}

int main(int argc, char** argv)
{
    timer_t timerid = 0;
    struct itimerspec it;
    struct sigevent evp;

    memset(&evp, 0, sizeof(struct sigevent));

    evp.sigev_value.sival_int = 111;
    evp.sigev_notify = SIGEV_THREAD;
    evp.sigev_notify_function = timer_thread;
    if (timer_create(CLOCK_REALTIME, &evp, &timerid) == -1)  
    {  
        perror("fail to timer_create");  
        return -1;;  
    }  
 
    printf("timer_create timerid = %d\n", timerid);
    it.it_interval.tv_sec = 0;
    it.it_interval.tv_nsec = atoi(argv[1]);  
    it.it_value.tv_sec = 1;
    it.it_value.tv_nsec = 0;  

    if (timer_settime(&timerid, 0, &it, NULL) == -1)  
    {  
        perror("fail to timer_settime");  
        return -1;
    }  

    while(1) {
        sleep(1);
    }
    return 0;
}

编译如下：

csky-abiv2-linux-g++ pthread_4simu.cc -o pthread_4simu -lpthread --std=c++11 -lrt

 创建顺序执行四个任务：

#include <pthread.h>
#include <unistd.h>
#include <thread>
#include <stdio.h>
#include <time.h>
#include <stdlib.h>
#include <signal.h>
#include <string.h>


unsigned int count = 0;
#define LOOP_COUNT 40000

void thread_fn(void)
{
    unsigned int i, a;
    for(i = 0; i < LOOP_COUNT; i++) {
        a++;
    }
}

void timer_thread(union sigval v)
{
    //printf("loop count=%d.\n", count++);

    thread_fn();
    thread_fn();
    thread_fn();
    thread_fn();
}

int main(int argc, char** argv)
{
    timer_t timerid = 0;
    struct itimerspec it;
    struct sigevent evp;

    memset(&evp, 0, sizeof(struct sigevent));

    evp.sigev_value.sival_int = 111;
    evp.sigev_notify = SIGEV_THREAD;
    evp.sigev_notify_function = timer_thread;
    if (timer_create(CLOCK_REALTIME, &evp, &timerid) == -1)  
    {  
        perror("fail to timer_create");  
        return -1;;  
    }  
 
    printf("timer_create timerid = %d\n", timerid);
    it.it_interval.tv_sec = 0;
    it.it_interval.tv_nsec = atoi(argv[1]);  
    it.it_value.tv_sec = 1;
    it.it_value.tv_nsec = 0;  

    if (timer_settime(&timerid, 0, &it, NULL) == -1)  
    {  
        perror("fail to timer_settime");  
        return -1;
    }  

    while(1) {
        sleep(1);
    }
    return 0;
}

编译如下：

csky-abiv2-linux-g++ loop.cc -o loop -lrt

2.2 测试结果

分别采用不同周期(5ms、10ms、25ms、40ms、100ms)，对两种方式进行测试结果如下。

	loop	pthread_4simu	分析
5ms			两者总的CPU占用率相差20%,
10ms			两者总的CPU占用率相差18%
25ms			两者总的CPU占用率相差8%
40ms			两者总的CPU占用率相差1%
100ms			两者总的CPU占用率基本持平

说明起线程执行任务，开销还是存在的；在新建线程数量较小情况下，对CPU占用率影响较低。但是随着新建线程数量增加，对CPU占用率的影响会越来越明显，严重时系统调度能力会下降。

3. 解决方法

针对线程名混乱的情况，在有了线程树形结构之后，结合代码比较容易找到入口点，修改线程名称prctl()/pthread_setname_np()。

修改usb_server_list:179的处理方式，改成单线程处理任务。一是降低系统线程创建销毁的开销，二是让top统计CPU占用率更加准确。

有了这两者，就可以明确线程占用率和功能对应关系，进入具体线程进行分析。