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

本文主要是介绍一个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=0cat-165   [000] ...1    53.738804: task_rename: pid=165 oldcomm=sh newcomm=cat oom_score_adj=0sh-153   [000] ....    84.638270: task_newtask: pid=166 comm=sh clone_flags=1200011 oom_score_adj=0xchip_runtime-166   [000] ...1    84.645910: task_rename: pid=166 oldcomm=sh newcomm=xchip_runtime oom_score_adj=0xchip_runtime-166   [000] ....    85.098260: task_newtask: pid=167 comm=xchip_runtime clone_flags=3d0f00 oom_score_adj=0Log2Hostflush-167   [000] ...1    85.099145: task_rename: pid=167 oldcomm=xchip_runtime newcomm=Log2Hostflush oom_score_adj=0xchip_runtime-166   [000] ....    85.133881: task_newtask: pid=168 comm=xchip_runtime clone_flags=3d0f00 oom_score_adj=0usb_server_list-168   [000] ...1    85.134077: task_rename: pid=168 oldcomm=xchip_runtime newcomm=usb_server_list oom_score_adj=0usb_server_list-168   [000] ....   116.497292: task_newtask: pid=169 comm=usb_server_list clone_flags=3d0f00 oom_score_adj=0coreComm-169   [000] ...1   116.501998: task_rename: pid=169 oldcomm=usb_server_list newcomm=coreComm oom_score_adj=0usb_server_list-168   [000] ....   116.514232: task_newtask: pid=170 comm=usb_server_list clone_flags=3d0f00 oom_score_adj=0

请问下怎么通过trace event抓取到/sys/kernel/debug/tracing/events/task/task_newtask的数据

echo 1 > /sys/kernel/debug/tracing/events/enable
/sys/kernel/debug/tracing/events/task/task_newtask enble
echo 1 > /sys/kernel/debug/tracing/tracing_on
cat /sys/kernel/debug/tracing/trace > /sdcard/trace.txt

cat /sys/kernel/debug/tracing/trace|grep -E 'task_rename|task_newtask'

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

在jupyter-notebook中读取trace.txt文件，然后从中提取关键信息，pid、comm、父pid、子pid列表。
以pid为字典键值，分析过程如下。

import reprocess_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):continueproc = 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=0task_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=0task_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']+':'+keyfor child1 in item['child']:print "    |-2-"+process_tree[child1]['comm']+':'+child1for child2 in process_tree[child1]['child']:print "        |-3-"+process_tree[child2]['comm']+':'+child2for child3 in process_tree[child2]['child']:print "            |-4-"+process_tree[child3]['comm']+':'+child3for child4 in process_tree[child3]['child']:print "                |-5-"+process_tree[child4]['comm']+':'+child4for child5 in process_tree[child4]['child']:print "                    |-6-"+process_tree[child5]['comm']+':'+child5for child6 in process_tree[child5]['child']:print "                        |-7-"+process_tree[child6]['comm']+':'+child6for 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 40000void 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 40000void 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)，对两种方式进行测试结果如下
https://www.cnblogs.com/arnoldlu/p/12112225.html
说明起线程执行任务，开销还是存在的；在新建线程数量较小情况下，对CPU占用率影响较低。但是随着新建线程数量增加，对CPU占用率的影响会越来越明显，严重时系统调度能力会下降。