Linux启动时间优化-内核和用户空间启动优化实践

关键词：initcall、bootgraph.py、bootchartd、pybootchart等。

启动时间的优化，分为两大部分，分别是内核部分和用户空间两大部分。

从内核timestamp 0.000000作为内核启动起点，到free_initmem()输出"Freeing init memory"作为内核启动的终点。

借助于bootgraph.py对内核的kmsg进行分析，输出bootgraph.html和initcall耗时csv文件。

在紧接着free_initmem()下面，是init进程的启动，作为用户空间的起点。内核的终点和用户空间的起点基本上可以任务无缝衔接。

用户空间借助bootchartd抓取/proc/uptime、/proc/stat、/proc/diskstats、/proc/xxx/stat、/proc/meminfo信息，最后打包到bootlog.tgz。

pybootchart.py对bootlog.tgz进行解析，并生成关于CPU占用率、Memory使用情况、磁盘吞吐率以及各进程执行情况的图标。

基于以上内核和用户空间输出，可以发现initcall和进程启动的异常情况。

比如哪个initcall耗时异常；哪个进程启动耗时过长，可以进入进程启动函数查看是否有阻塞等情况。

1. 内核启动优化

在内核源码中自带了一个工具(scripts/bootgraph.pl)用于分析启动时间，这个工具生成output.svg。

但是bootgraph.py生成的结果可读性更好，也更加容易发现问题。

1.1 准备工作

对内核的修改包括，initcall_debug和CONFIG_LOG_BUF_SHIFT。

1.1.1 打开initcall_debug

bool initcall_debug = true;

这样做的目的是在内核kmsg中记录每个initcall的calling和initcall时间，本工具分析依赖于这些kmsg。

static int __init_or_module do_one_initcall_debug(initcall_t fn)
{
    ktime_t calltime, delta, rettime;
    unsigned long long duration;
    int ret;

    printk(KERN_DEBUG "calling  %pF @ %i
", fn, task_pid_nr(current));-----------------------initcall开始log
    calltime = ktime_get();
    ret = fn();
    rettime = ktime_get();
    delta = ktime_sub(rettime, calltime);
    duration = (unsigned long long) ktime_to_ns(delta) >> 10;
    printk(KERN_DEBUG "initcall %pF returned %d after %lld usecs
", fn,
        ret, duration);-----------------------------------------------------------------------initcall结束log

    return ret;
}

int __init_or_module do_one_initcall(initcall_t fn)
{
    int count = preempt_count();
    int ret;

    if (initcall_debug)
        ret = do_one_initcall_debug(fn);
    else
        ret = fn();
...
}

1.1.2 增大log_buf空间

log_buf用于存放printk消息，他类似于RingBuffer，超出部分会覆盖头部。

#define __LOG_BUF_LEN    (1 << CONFIG_LOG_BUF_SHIFT)

static char __log_buf[__LOG_BUF_LEN];
static char *log_buf = __log_buf;

所以将CONFIG_LOG_BUF_SHIFT从16增加到18，即log_buf空间从64K增加到256K。

1.1.3 对bootgraph.py的改进

1.1.3.1 划分内核启动的起点终点

界定内核启动的起点很容易，从时间0开始。

用户空间的起点是init进程，所以将内核空间的终点放在启动init进程之前。

这样就可以清晰看到initcall在整个内核初始化中的位置。

static inline int free_area(unsigned long pfn, unsigned long end, char *s)
{
    unsigned int pages = 0, size = (end - pfn) << (PAGE_SHIFT - 10);
...
    if (size && s)
        printk(KERN_INFO "Freeing %s memory: %dK
", s, size);-------------输出“Freeing init memory:”到kmsg中。

    return pages;
}

void free_initmem(void)
{
...
    if (!machine_is_integrator() && !machine_is_cintegrator())
        totalram_pages += free_area(__phys_to_pfn(__pa(__init_begin)),
                        __phys_to_pfn(__pa(__init_end)),
                        "init");
}

static noinline int init_post(void)
{
    /* need to finish all async __init code before freeing the memory */
    async_synchronize_full();
    free_initmem();------------------------------------------------------------内核空间的终点
...
    run_init_process("/sbin/init");--------------------------------------------用户空间的起点
    run_init_process("/etc/init");
    run_init_process("/bin/init");
    run_init_process("/bin/sh");
...
}

基于“Freeing init memory”对内核和用户空间初始化进行划分，Split kernel and userspace by free_area()。

commit 6195fa73b5522ec5f2461932c894421c30fc3cd7
Author: Arnold Lu <arnoldlu@qq.com>
Date:   Tue Jun 19 22:49:09 2018 +0800

    Split kernel and userspace by free_area()

diff --git a/bootgraph.py b/bootgraph.py
index 8ee626c..dafe359 100755
--- a/bootgraph.py
+++ b/bootgraph.py
@@ -63,6 +63,7 @@ class SystemValues(aslib.SystemValues):
     timeformat = '%.6f'
     bootloader = 'grub'
     blexec = []
+    last_init=0
     def __init__(self):
         self.hostname = platform.node()
         self.testtime = datetime.now().strftime('%Y-%m-%d_%H:%M:%S')
@@ -223,7 +224,7 @@ class Data(aslib.Data):
             'kernel': {'list': dict(), 'start': -1.0, 'end': -1.0, 'row': 0,
                 'order': 0, 'color': 'linear-gradient(to bottom, #fff, #bcf)'},
             'user': {'list': dict(), 'start': -1.0, 'end': -1.0, 'row': 0,
-                'order': 1, 'color': '#fff'}
+                'order': 1, 'color': 'linear-gradient(to bottom, #456, #cde)'}
         }
     def deviceTopology(self):
         return ''
@@ -345,17 +346,18 @@ def parseKernelLog():
         m = re.match('^initcall *(?P<f>.*)+.* returned (?P<r>.*) after (?P<t>.*) usecs', msg)
         if(m):
             data.valid = True
-            data.end = ktime
+            sysvals.last_init = '%.0f'%(ktime*1000)
             f, r, t = m.group('f', 'r', 't')
             if(f in devtemp):
                 start, pid = devtemp[f]
                 data.newAction(phase, f, pid, start, ktime, int(r), int(t))
                 del devtemp[f]
             continue
-        if(re.match('^Freeing unused kernel memory.*', msg)):
+        if(re.match('^Freeing init kernel memory.*', msg)):
             data.tUserMode = ktime
             data.dmesg['kernel']['end'] = ktime
             data.dmesg['user']['start'] = ktime
+            data.end = ktime+0.1
             phase = 'user'
 
     if tp.stamp:
@@ -531,8 +533,8 @@ def createBootGraph(data):
         print('ERROR: No timeline data')
         return False
     user_mode = '%.0f'%(data.tUserMode*1000)
-    last_init = '%.0f'%(tTotal*1000)
-    devtl.html += html_timetotal.format(user_mode, last_init)
+    #last_init = '%.0f'%(tTotal*1000)
+    devtl.html += html_timetotal.format(user_mode, sysvals.last_init)
 
     # determine the maximum number of rows we need to draw
     devlist = []

1.1.3.2 将每个initcall启动记录到csv

图形化的好处就是直观，但是有时候需要更准确的数据进行排序分析。

这时候生成excel数据，进行处理就很方便了。

增加下面代码会在生成bootgraph.html的同时生成devinit.csv文件，Record data to csv file.。

commit 7bcb705ed30b1e1a0ca3385d01b412f8e6f23b4e
Author: Arnold Lu <arnoldlu@qq.com>
Date:   Tue Jun 19 22:52:43 2018 +0800

    Record data to csv file.

diff --git a/bootgraph.py b/bootgraph.py
index dafe359..7f43cb7 100755
--- a/bootgraph.py
+++ b/bootgraph.py
@@ -33,6 +33,7 @@ import shutil
 from datetime import datetime, timedelta
 from subprocess import call, Popen, PIPE
 import sleepgraph as aslib
+import csv
 
 # ----------------- CLASSES --------------------
 
@@ -48,6 +49,7 @@ class SystemValues(aslib.SystemValues):
     kernel = ''
     dmesgfile = ''
     ftracefile = ''
+    csvfile = 'devinit.csv'
     htmlfile = 'bootgraph.html'
     testdir = ''
     kparams = ''
@@ -300,6 +302,9 @@ def parseKernelLog():
         lf = open(sysvals.dmesgfile, 'r')
     else:
         lf = Popen('dmesg', stdout=PIPE).stdout
+    csvfile = open(sysvals.csvfile, 'wb');
+    csvwriter = csv.writer(csvfile)
+    csvwriter.writerow(['Func', 'Start(ms)', 'End(ms)', 'Duration(ms)', 'Return'])
     for line in lf:
         line = line.replace('
', '')
         # grab the stamp and sysinfo
@@ -351,6 +356,7 @@ def parseKernelLog():
             if(f in devtemp):
                 start, pid = devtemp[f]
                 data.newAction(phase, f, pid, start, ktime, int(r), int(t))
+                csvwriter.writerow([f, start*1000, ktime*1000, float(t)/1000, int(r)]);
                 del devtemp[f]
             continue
         if(re.match('^Freeing init kernel memory.*', msg)):
@@ -364,6 +370,7 @@ def parseKernelLog():
         sysvals.stamp = 0
         tp.parseStamp(data, sysvals)
     data.dmesg['user']['end'] = data.end
+    csvfile.close()
     lf.close()
     return data

1.2 生成测试结果

执行如下命令生成两个文件bootgraph.html和devinit.csv。

bootgraph.py依赖于kmsg中的“calling”/“initcall”识别initcall的起点终点，依赖“Freeing init memory”作为内核启动终点。

./bootgraph.py -dmesg kmsg.txt -addlogs

 PS：下面两张截图都覆盖了函数名称。

1.2.1 bootgraph.html分析

从下面的图可以看出内核的初始化持续到2672ms处，然后整个内核初始化主要部分就是initcall。

同时从上面可以看出哪几个initcall占用时间较长，点击可以看到持续多久、是否成功等信息。

1.2.2 devinit.csv分析

相对于bootgraph.html，devinit.csv更容易进行量化。

对devinit.csv按照Duration进行降序，可以看出占用靠前的initcall。

1.3 优化实例

1.3.1 串口log优化

对于115200的串口速率来说，一个字符耗时大概1/(115200/10)=0.087ms。所以100个字符大概耗时8.7ms。

在内核初始化的时候，输出很多串口log是一件恐怖的事情。

虽然不是什么高深的技巧，但是却很有效。

1.3.1.1 初始状态

在没有打开initcall_debug，console_printk采用默认配置情况下，内核启动总共耗时2881ms。

<6>[    2.881049] Freeing init memory: 340K

1.3.1.2 打开initcall_debug

在打开initcall_debug用于调试之后，引入了额外的开销。

但又不得不借助于initcall_debug来发现问题。

内核启动共耗时3404ms，引入了523ms开销。

关于initcall耗时列表如下： 

1.3.1.3 打开initcall_debug，关闭console显示

在关闭了console显示过后，串口被最大化的关闭。

内核共耗时1281ms，相较原始状态减少了1600ms。也就是说整个内核初始化的一大半时间被节省了。

 在关闭串口console之后，可以看出initcall的时间大大减少了。

 

1.3.2 优化耗时top10的initcall

参见上图列表，进入initcall进行优化。

2. 用户空间启动优化

用户空间的优化依赖于bootchartd获取log，然后使用pybootchart.py进行分析。

下面分几部分进行分析：如何在busybox中使能bootchartd；对bootchartd进行简单分析；对pybootchart.py进行简单分析；最后对测试结果进行分析。

2.1 使能bootchartd

要使能bootchartd，需要修改命令行参数以支持从bootchartd启动init；bootchartd本身以及tar、dmesg等支持。

2.1.1 bootloader中修改命令行参数增加

修改bootloader中传递给Linux的命令行参数，如果bootchartd放在ramfs中，使用rdinit=/sbin/bootchartd。

如果bootchartd放在非ramfs中：

init=/sbin/bootchartd

如此使用bootchartd作为init，然后再用bootchartd去启动/sbin/init。

Linux内核init_setup()函数从cmdline解析出init参数，赋给execute_command。

然后在init_post()中就会使用run_init_process()。

static int __init init_setup(char *str)
{
    unsigned int i;

    execute_command = str;------------------------------------------从cmdline中解析出init的值，赋给execute_command。
    /*
     * In case LILO is going to boot us with default command line,
     * it prepends "auto" before the whole cmdline which makes
     * the shell think it should execute a script with such name.
     * So we ignore all arguments entered _before_ init=... [MJ]
     */
    for (i = 1; i < MAX_INIT_ARGS; i++)
        argv_init[i] = NULL;
    return 1;
}
__setup("init=", init_setup);

static noinline int init_post(void)
{
...
    free_initmem();
...
    if (execute_command) {
        run_init_process(execute_command);---------------------------如果execute_command被赋值，那么作为init进程进行初始化。如果成功，后面的run_init_process()不会被执行。
        printk(KERN_WARNING "Failed to execute %s.  Attempting "
                    "defaults...
", execute_command);
    }
    run_init_process("/sbin/init");
    run_init_process("/etc/init");
    run_init_process("/bin/init");
    run_init_process("/bin/sh");

    panic("No init found.  Try passing init= option to kernel. "
          "See Linux Documentation/init.txt for guidance.");
}

2.1.2 内核中修改busybox

内核中需要打开bootchartd选项、同时还需要支持tar，因为需要对生成的文件进行打包。

由于需要获取内核kmsg，所以需要dmesg支持。

CONFIG_FEATURE_SEAMLESS_GZ=y
CONFIG_GUNZIP=y
CONFIG_GZIP=y
CONFIG_FEATURE_GZIP_LONG_OPTIONS=y
CONFIG_TAR=y
CONFIG_FEATURE_TAR_CREATE=y
CONFIG_FEATURE_TAR_AUTODETECT=y
CONFIG_FEATURE_TAR_FROM=y
CONFIG_FEATURE_TAR_OLDGNU_COMPATIBILITY=y
CONFIG_FEATURE_TAR_OLDSUN_COMPATIBILITY=y
CONFIG_FEATURE_TAR_GNU_EXTENSIONS=y
CONFIG_FEATURE_TAR_LONG_OPTIONS=y
CONFIG_FEATURE_TAR_TO_COMMAND=y
CONFIG_FEATURE_TAR_UNAME_GNAME=y
CONFIG_FEATURE_TAR_NOPRESERVE_TIME=y
CONFIG_BOOTCHARTD=y
CONFIG_FEATURE_BOOTCHARTD_BLOATED_HEADER=y
CONFIG_DMESG=y

2.1.3 对bootchartd的调整

对bootchartd的配置可以通过指定配置文件，ENABLE_FEATURE_BOOTCHARTD_CONFIG_FILE。

或者通过修改sample_period_us和process_accounting。

int bootchartd_main(int argc, char **argv) MAIN_EXTERNALLY_VISIBLE;
int bootchartd_main(int argc UNUSED_PARAM, char **argv)
{
...
    /* Read config file: */
    sample_period_us = 200 * 1000;-----------------------------------如果觉得粒度不够，丢失细节，可以提高采样频率查看更多细节。但代价是bootchard占用更多CPU资源。
    process_accounting = 0;
    if (ENABLE_FEATURE_BOOTCHARTD_CONFIG_FILE) {
        char* token[2];
        parser_t *parser = config_open2("/etc/bootchartd.conf" + 5, fopen_for_read);
        if (!parser)
            parser = config_open2("/etc/bootchartd.conf", fopen_for_read);
        while (config_read(parser, token, 2, 0, "#=", PARSE_NORMAL & ~PARSE_COLLAPSE)) {
            if (strcmp(token[0], "SAMPLE_PERIOD") == 0 && token[1])
                sample_period_us = atof(token[1]) * 1000000;
            if (strcmp(token[0], "PROCESS_ACCOUNTING") == 0 && token[1]
             && (strcmp(token[1], "on") == 0 || strcmp(token[1], "yes") == 0)
            ) {
                process_accounting = 1;
            }
        }
        config_close(parser);
        if ((int)sample_period_us <= 0)
            sample_period_us = 1; /* prevent division by 0 */
    }
...
    return EXIT_SUCCESS;
}

2.1.4 增加meminfo、dmesg

打开对/proc/meminfo的解析，原始数据保存在proc_meminfo.log中。

同时保存内核kmsg到dmesg中。

@@ -212,6 +212,7 @@
 {
     FILE *proc_stat = xfopen("proc_stat.log", "w");
     FILE *proc_diskstats = xfopen("proc_diskstats.log", "w");
+    FILE *proc_meminfo = xfopen("proc_meminfo.log", "w");
     //FILE *proc_netdev = xfopen("proc_netdev.log", "w");
     FILE *proc_ps = xfopen("proc_ps.log", "w");
     int look_for_login_process = (getppid() == 1);
@@ -240,6 +241,7 @@
 
         dump_file(proc_stat, "/proc/stat");
         dump_file(proc_diskstats, "/proc/diskstats");
+        dump_file(proc_meminfo, "/proc/meminfo");
         //dump_file(proc_netdev, "/proc/net/dev");
         if (dump_procs(proc_ps, look_for_login_process)) {
             /* dump_procs saw a getty or {g,k,x}dm
@@ -306,8 +308,11 @@
     }
     fclose(header_fp);
 
+    system(xasprintf("dmesg >dmesg"));
+
     /* Package log files */
-    system(xasprintf("tar -zcf /var/log/bootlog.tgz header %s *.log", process_accounting ? "kernel_pacct" : ""));
+    //system(xasprintf("tar -zcf /var/log/bootlog.tgz header %s *.log", process_accounting ? "kernel_pacct" : ""));
+    system(xasprintf("tar -zcf /var/log/bootlog.tgz header dmesg %s *.log", process_accounting ? "kernel_pacct" : ""));
     /* Clean up (if we are not in detached tmpfs) */
     if (tempdir) {
         unlink("header");
@@ -315,6 +320,7 @@
         unlink("proc_diskstats.log");
         //unlink("proc_netdev.log");
         unlink("proc_ps.log");
+        unlink("dmesg");
         if (process_accounting)
             unlink("kernel_pacct");
         rmdir(tempdir);

2.2 bootchartd分析

bootchartd的入口点是bootchartd_main()函数。

在bootchartd_main中主要就是解析start/init/stop参数。如果使能bootchartd.conf的话，解析出sample_period_us和process_accounting。

bootchartd_main()主要通过do_logging()收集log和finalize()做打包收尾工作。

static void do_logging(unsigned sample_period_us, int process_accounting)
{
    FILE *proc_stat = xfopen("proc_stat.log", "w");
    FILE *proc_diskstats = xfopen("proc_diskstats.log", "w");
    FILE *proc_meminfo = xfopen("proc_meminfo.log", "w");
    //FILE *proc_netdev = xfopen("proc_netdev.log", "w");
    FILE *proc_ps = xfopen("proc_ps.log", "w");
    int look_for_login_process = (getppid() == 1);
    unsigned count = 60*1000*1000 / sample_period_us; /* ~1 minute */--------------------------最长统计1分钟时间bootchart

    if (process_accounting) {
        close(xopen("kernel_pacct", O_WRONLY | O_CREAT | O_TRUNC));
        acct("kernel_pacct");
    }

    while (--count && !bb_got_signal) {--------------------------------------------------------如果满足count为0或者bb_got_signal，则停止采样。
        char *p;
        int len = open_read_close("/proc/uptime", G.jiffy_line, sizeof(G.jiffy_line)-2);
        if (len < 0)
            goto wait_more;
        /* /proc/uptime has format "NNNNNN.MM NNNNNNN.MM" */
        /* we convert it to "NNNNNNMM
" (using first value) */
        G.jiffy_line[len] = '';
        p = strchr(G.jiffy_line, '.');
        if (!p)
            goto wait_more;
        while (isdigit(*++p))
            p[-1] = *p;
        p[-1] = '
';
        p[0] = '';

        dump_file(proc_stat, "/proc/stat");---------------------------------------------------保存/proc/stat到proc_stat.og中
        dump_file(proc_diskstats, "/proc/diskstats");-----------------------------------------保存/proc/diskstats到proc_diskstats.log中
        dump_file(proc_meminfo, "/proc/meminfo");---------------------------------------------保存/proc/meminfo到proc_meminfo.log中
        //dump_file(proc_netdev, "/proc/net/dev");
        if (dump_procs(proc_ps, look_for_login_process)) {------------------------------------遍历/proc下所有进程到proc_ps.log中
            /* dump_procs saw a getty or {g,k,x}dm
             * stop logging in 2 seconds:
             */
            if (count > 2*1000*1000 / sample_period_us)
                count = 2*1000*1000 / sample_period_us;
        }
        fflush_all();
 wait_more:
        usleep(sample_period_us);-------------------------------------------------------------每次采样后睡眠sample_period_us，达到周期性的目的。
    }
}

dump_procs()处理/proc目录下每个pid的stat文件。

static int dump_procs(FILE *fp, int look_for_login_process)
{
    struct dirent *entry;
    DIR *dir = opendir("/proc");
    int found_login_process = 0;

    fputs(G.jiffy_line, fp);
    while ((entry = readdir(dir)) != NULL) {------------------------------------遍历/proc目录，返回entry是struct dirent数据结构
        char name[sizeof("/proc/%u/cmdline") + sizeof(int)*3];
        int stat_fd;
        unsigned pid = bb_strtou(entry->d_name, NULL, 10);----------------------这里只取数字类型，其它目录则continue。
        if (errno)
            continue;

        /* Android's version reads /proc/PID/cmdline and extracts
         * non-truncated process name. Do we want to do that? */

        sprintf(name, "/proc/%u/stat", pid);
        stat_fd = open(name, O_RDONLY);
        if (stat_fd >= 0) {
            char *p;
            char stat_line[4*1024];
            int rd = safe_read(stat_fd, stat_line, sizeof(stat_line)-2);

            close(stat_fd);
            if (rd < 0)
                continue;
            stat_line[rd] = '';
            p = strchrnul(stat_line, '
');
            *p++ = '
';
            *p = '';
            fputs(stat_line, fp);----------------------------------------------保存读取的/proc/xxx/stat到fp中
            if (!look_for_login_process)
                continue;
...
        }
    }
    closedir(dir);
    fputc('
', fp);
    return found_login_process;
}

finalize()生成header、dmesg，然后和do_logging()中生成的文件一起打包到bootlog.tgz中。

static void finalize(char *tempdir, const char *prog, int process_accounting)
{
    //# Stop process accounting if configured
    //local pacct=
    //[ -e kernel_pacct ] && pacct=kernel_pacct

    FILE *header_fp = xfopen("header", "w");

    if (process_accounting)
        acct(NULL);

    if (prog)
        fprintf(header_fp, "profile.process = %s
", prog);

    fputs("version = "BC_VERSION_STR"
", header_fp);
    if (ENABLE_FEATURE_BOOTCHARTD_BLOATED_HEADER) {
        char *hostname;
        char *kcmdline;
        time_t t;
        struct tm tm_time;
        /* x2 for possible localized weekday/month names */
        char date_buf[sizeof("Mon Jun 21 05:29:03 CEST 2010") * 2];
        struct utsname unamebuf;

        hostname = safe_gethostname();
        time(&t);
        localtime_r(&t, &tm_time);
        strftime(date_buf, sizeof(date_buf), "%a %b %e %H:%M:%S %Z %Y", &tm_time);
        fprintf(header_fp, "title = Boot chart for %s (%s)
", hostname, date_buf);
        if (ENABLE_FEATURE_CLEAN_UP)
            free(hostname);

        uname(&unamebuf); /* never fails */
        /* same as uname -srvm */
        fprintf(header_fp, "system.uname = %s %s %s %s
",
                unamebuf.sysname,
                unamebuf.release,
                unamebuf.version,
                unamebuf.machine
        );

        //system.release = `cat /etc/DISTRO-release`
        //system.cpu = `grep '^model name' /proc/cpuinfo | head -1` ($cpucount)

        kcmdline = xmalloc_open_read_close("/proc/cmdline", NULL);
        /* kcmdline includes trailing "
" */
        fprintf(header_fp, "system.kernel.options = %s", kcmdline);
        if (ENABLE_FEATURE_CLEAN_UP)
            free(kcmdline);
    }
    fclose(header_fp);

    system(xasprintf("dmesg >dmesg"));

    /* Package log files */
    //system(xasprintf("tar -zcf /var/log/bootlog.tgz header %s *.log", process_accounting ? "kernel_pacct" : ""));
    system(xasprintf("tar -zcf /var/log/bootlog.tgz header dmesg %s *.log", process_accounting ? "kernel_pacct" : ""));
    /* Clean up (if we are not in detached tmpfs) */
    if (tempdir) {
        unlink("header");
        unlink("proc_stat.log");
        unlink("proc_diskstats.log");
        //unlink("proc_netdev.log");
        unlink("proc_ps.log");
        unlink("dmesg");
        if (process_accounting)
            unlink("kernel_pacct");
        rmdir(tempdir);
    }

    /* shell-based bootchartd tries to run /usr/bin/bootchart if $AUTO_RENDER=yes:
     * /usr/bin/bootchart -o "$AUTO_RENDER_DIR" -f $AUTO_RENDER_FORMAT "$BOOTLOG_DEST"
     */
}

2.3 pybootchart分析

pybootchart主要分为两大部分：解析和画图。

 从_do_parse()中可以看出解析的数据是从哪个log文件中获取的。而这些log文件是由do_logging()从内核节点获取的。

通过_do_parse()和do_logging()两函数，就可以明白生成结果图表中数据在内核中的对应意义。

2.3.1 pybootchart解析bootload.tgz

pybootchart在解析这些log文件的时候，同时解析了从/proc/uptime获取的时间作为时间轴。 

def _do_parse(writer, state, name, file):
    writer.status("parsing '%s'" % name)
    t1 = clock()
    if name == "header":
        state.headers = _parse_headers(file)
    elif name == "proc_diskstats.log":
        state.disk_stats = _parse_proc_disk_stat_log(file, get_num_cpus(state.headers))
    elif name == "taskstats.log":
        state.ps_stats = _parse_taskstats_log(writer, file)
        state.taskstats = True
    elif name == "proc_stat.log":
        state.cpu_stats = _parse_proc_stat_log(file)
    elif name == "proc_meminfo.log":
        state.mem_stats = _parse_proc_meminfo_log(file)
    elif name == "dmesg":
        state.kernel = _parse_dmesg(writer, file)
    elif name == "cmdline2.log":
        state.cmdline = _parse_cmdline_log(writer, file)
    elif name == "paternity.log":
        state.parent_map = _parse_paternity_log(writer, file)
    elif name == "proc_ps.log":  # obsoleted by TASKSTATS
        state.ps_stats = _parse_proc_ps_log(writer, file)
    elif name == "kernel_pacct": # obsoleted by PROC_EVENTS
        state.parent_map = _parse_pacct(writer, file)
    t2 = clock()
    writer.info("  %s seconds" % str(t2-t1))
    return state

2.3.2 pybootchart画图

 经过__do_parse()解析的结果，在render()中进行渲染。

#
# Render the chart.
#
def render(ctx, options, xscale, trace):
    (w, h) = extents (options, xscale, trace)
    global OPTIONS
    OPTIONS = options.app_options

    proc_tree = options.proc_tree (trace)

    # x, y, w, h
    clip = ctx.clip_extents()

    sec_w = int (xscale * sec_w_base)
    ctx.set_line_width(1.0)
    ctx.select_font_face(FONT_NAME)
    draw_fill_rect(ctx, WHITE, (0, 0, max(w, MIN_IMG_W), h))
    w -= 2*off_x
    # draw the title and headers
    if proc_tree.idle:
        duration = proc_tree.idle
    else:
        duration = proc_tree.duration

    if not options.kernel_only:
        curr_y = draw_header (ctx, trace.headers, duration)
    else:
        curr_y = off_y;

    if options.charts:
        curr_y = render_charts (ctx, options, clip, trace, curr_y, w, h, sec_w)

    # draw process boxes
    proc_height = h
    if proc_tree.taskstats and options.cumulative:
        proc_height -= CUML_HEIGHT

    draw_process_bar_chart(ctx, clip, options, proc_tree, trace.times,
                   curr_y, w, proc_height, sec_w)

    curr_y = proc_height
    ctx.set_font_size(SIG_FONT_SIZE)
    draw_text(ctx, SIGNATURE, SIG_COLOR, off_x + 5, proc_height - 8)

    # draw a cumulative CPU-time-per-process graph
    if proc_tree.taskstats and options.cumulative:
        cuml_rect = (off_x, curr_y + off_y, w, CUML_HEIGHT/2 - off_y * 2)
        if clip_visible (clip, cuml_rect):
            draw_cuml_graph(ctx, proc_tree, cuml_rect, duration, sec_w, STAT_TYPE_CPU)

    # draw a cumulative I/O-time-per-process graph
    if proc_tree.taskstats and options.cumulative:
        cuml_rect = (off_x, curr_y + off_y * 100, w, CUML_HEIGHT/2 - off_y * 2)
        if clip_visible (clip, cuml_rect):
            draw_cuml_graph(ctx, proc_tree, cuml_rect, duration, sec_w, STAT_TYPE_IO)

 渲染图表的主要工作在render_charts()中完成。

def render_charts(ctx, options, clip, trace, curr_y, w, h, sec_w):
    proc_tree = options.proc_tree(trace)

    # render bar legend
    ctx.set_font_size(LEGEND_FONT_SIZE)

    draw_legend_box(ctx, "CPU (user+sys)", CPU_COLOR, off_x, curr_y+20, leg_s)-----------------------CPU占用率部分
    draw_legend_box(ctx, "I/O (wait)", IO_COLOR, off_x + 120, curr_y+20, leg_s)

    # render I/O wait
    chart_rect = (off_x, curr_y+30, w, bar_h)
    if clip_visible (clip, chart_rect):
        draw_box_ticks (ctx, chart_rect, sec_w)
        draw_annotations (ctx, proc_tree, trace.times, chart_rect)
        draw_chart (ctx, IO_COLOR, True, chart_rect, 
                [(sample.time, sample.user + sample.sys + sample.io) for sample in trace.cpu_stats], 
                proc_tree, None)
        # render CPU load
        draw_chart (ctx, CPU_COLOR, True, chart_rect, 
                [(sample.time, sample.user + sample.sys) for sample in trace.cpu_stats], 
                proc_tree, None)

    curr_y = curr_y + 30 + bar_h

    # render second chart
    draw_legend_line(ctx, "Disk throughput", DISK_TPUT_COLOR, off_x, curr_y+20, leg_s)---------------磁盘吞吐率部分
    draw_legend_box(ctx, "Disk utilization", IO_COLOR, off_x + 120, curr_y+20, leg_s)

        # render I/O utilization
    chart_rect = (off_x, curr_y+30, w, bar_h)
    if clip_visible (clip, chart_rect):
        draw_box_ticks (ctx, chart_rect, sec_w)
        draw_annotations (ctx, proc_tree, trace.times, chart_rect)
        draw_chart (ctx, IO_COLOR, True, chart_rect, 
                [(sample.time, sample.util) for sample in trace.disk_stats], 
                proc_tree, None)

    # render disk throughput
    max_sample = max (trace.disk_stats, key = lambda s: s.tput)
    if clip_visible (clip, chart_rect):
        draw_chart (ctx, DISK_TPUT_COLOR, False, chart_rect, 
                [(sample.time, sample.tput) for sample in trace.disk_stats], 
                proc_tree, None)

    pos_x = off_x + ((max_sample.time - proc_tree.start_time) * w / proc_tree.duration)

    shift_x, shift_y = -20, 20
    if (pos_x < off_x + 245):
        shift_x, shift_y = 5, 40

    label = "%dMB/s" % round ((max_sample.tput) / 1024.0)
    draw_text (ctx, label, DISK_TPUT_COLOR, pos_x + shift_x, curr_y + shift_y)

    curr_y = curr_y + 30 + bar_h

    # render mem usage
    chart_rect = (off_x, curr_y+30, w, meminfo_bar_h)
    mem_stats = trace.mem_stats
    if mem_stats and clip_visible (clip, chart_rect):
        #mem_scale = max(sample.records['MemTotal'] - sample.records['MemFree'] for sample in mem_stats)
        mem_scale = max(sample.records['MemTotal'] for sample in mem_stats)
        draw_legend_box(ctx, "Mem cached (scale: %u MiB)" % (float(mem_scale) / 1024), MEM_CACHED_COLOR, off_x, curr_y+20, leg_s)
        draw_legend_box(ctx, "Used", MEM_USED_COLOR, off_x + 240, curr_y+20, leg_s)
        draw_legend_box(ctx, "Buffers", MEM_BUFFERS_COLOR, off_x + 360, curr_y+20, leg_s)
        draw_legend_line(ctx, "Swap (scale: %u MiB)" % max([(sample.records['SwapTotal'] - sample.records['SwapFree'])/1024 for sample in mem_stats]), 
                 MEM_SWAP_COLOR, off_x + 480, curr_y+20, leg_s)
        draw_legend_box(ctx, "Free", MEM_FREE_COLOR, off_x + 700, curr_y+20, leg_s)
        draw_box_ticks(ctx, chart_rect, sec_w)
        draw_annotations(ctx, proc_tree, trace.times, chart_rect)

        draw_chart(ctx, MEM_FREE_COLOR, True, chart_rect, 
               [(sample.time, sample.records['MemTotal']) for sample in trace.mem_stats], 
               proc_tree, [0, mem_scale])
        draw_chart(ctx, MEM_BUFFERS_COLOR, True, chart_rect, 
               [(sample.time, sample.records['MemTotal'] - sample.records['MemFree']) for sample in trace.mem_stats], 
               proc_tree, [0, mem_scale])
        draw_chart(ctx, MEM_CACHED_COLOR, True, chart_rect, 
               [(sample.time, sample.records['MemTotal'] - sample.records['MemFree'] - sample.records['Buffers']) for sample in trace.mem_stats], 
               proc_tree, [0, mem_scale])
        draw_chart(ctx, MEM_USED_COLOR, True, chart_rect, 
               [(sample.time, sample.records['MemTotal'] - sample.records['MemFree'] - sample.records['Buffers'] - sample.records['Cached']) for sample in trace.mem_stats], 
               proc_tree, [0, mem_scale])
        draw_chart(ctx, MEM_SWAP_COLOR, False, chart_rect, 
               [(sample.time, float(sample.records['SwapTotal'] - sample.records['SwapFree'])) for sample in mem_stats], 
               proc_tree, None)
        curr_y = curr_y + meminfo_bar_h

    return curr_y

2.3.3 bootchart进程状态分析

bootchart对进程状态分析依赖于/proc/xxx/stat节点获取的信息，包括进程开始执行时间和终止时间，以及在此过程中的状态变化。

2.3.3.1 proc/xxx/stat解读

每个进程都有自己的一系列节点，bootchart的进程状态、起始点、终止点依赖于proc/xxx/stat节点的分析。

每个sample_period_us，bootchartd就会遍历/proc目录保存其中的stat信息。

stat信息通过do_task_stat()获取相关信息。

上面是proc_ps.log部分内容，可以看出和do_task_stat()中内容对应。

这些信息在pybootchart的__parse_proc_ps_log()中进行解析。

通过start_time可以确定进程的起始时间，然后不同时间的state确定进程在bootchart中的状态，ppid可以确定进程的父子关系，在bootchart中有虚线连接。

static const struct pid_entry tid_base_stuff[] = {
...
    ONE("stat",      S_IRUGO, proc_tid_stat),
...
}

int proc_tid_stat(struct seq_file *m, struct pid_namespace *ns,
            struct pid *pid, struct task_struct *task)
{
    return do_task_stat(m, ns, pid, task, 0);
}


static int do_task_stat(struct seq_file *m, struct pid_namespace *ns,
            struct pid *pid, struct task_struct *task, int whole)
{
    unsigned long vsize, eip, esp, wchan = ~0UL;
    long priority, nice;
    int tty_pgrp = -1, tty_nr = 0;
    sigset_t sigign, sigcatch;
    char state;
    pid_t ppid = 0, pgid = -1, sid = -1;
    int num_threads = 0;
    int permitted;
    struct mm_struct *mm;
    unsigned long long start_time;
    unsigned long cmin_flt = 0, cmaj_flt = 0;
    unsigned long  min_flt = 0,  maj_flt = 0;
    cputime_t cutime, cstime, utime, stime;
    cputime_t cgtime, gtime;
    unsigned long rsslim = 0;
    char tcomm[sizeof(task->comm)];
    unsigned long flags;
...
    /* scale priority and nice values from timeslices to -20..20 */
    /* to make it look like a "normal" Unix priority/nice value  */
    priority = task_prio(task);
    nice = task_nice(task);

    /* Temporary variable needed for gcc-2.96 */
    /* convert timespec -> nsec*/
    start_time =
        (unsigned long long)task->real_start_time.tv_sec * NSEC_PER_SEC
                + task->real_start_time.tv_nsec;
    /* convert nsec -> ticks */
    start_time = nsec_to_clock_t(start_time);---------------------------------------进程的启动时间，单位是ticks。

    seq_printf(m, "%d (%s) %c", pid_nr_ns(pid, ns), tcomm, state);------------------进程的pid、名称以及状态，状态在上一小节有介绍。
    seq_put_decimal_ll(m, ' ', ppid);-----------------------------------------------父进程pid。
    seq_put_decimal_ll(m, ' ', pgid);
    seq_put_decimal_ll(m, ' ', sid);
    seq_put_decimal_ll(m, ' ', tty_nr);
    seq_put_decimal_ll(m, ' ', tty_pgrp);
    seq_put_decimal_ull(m, ' ', task->flags);
    seq_put_decimal_ull(m, ' ', min_flt);
    seq_put_decimal_ull(m, ' ', cmin_flt);
    seq_put_decimal_ull(m, ' ', maj_flt);
    seq_put_decimal_ull(m, ' ', cmaj_flt);
    seq_put_decimal_ull(m, ' ', cputime_to_clock_t(utime));--------------------------用户空间消耗时间
    seq_put_decimal_ull(m, ' ', cputime_to_clock_t(stime));--------------------------内核空间消耗时间
    seq_put_decimal_ll(m, ' ', cputime_to_clock_t(cutime));
    seq_put_decimal_ll(m, ' ', cputime_to_clock_t(cstime));
    seq_put_decimal_ll(m, ' ', priority);
    seq_put_decimal_ll(m, ' ', nice);
    seq_put_decimal_ll(m, ' ', num_threads);
    seq_put_decimal_ull(m, ' ', 0);
    seq_put_decimal_ull(m, ' ', start_time);
    seq_put_decimal_ull(m, ' ', vsize);
    seq_put_decimal_ll(m, ' ', mm ? get_mm_rss(mm) : 0);
    seq_put_decimal_ull(m, ' ', rsslim);
    seq_put_decimal_ull(m, ' ', mm ? (permitted ? mm->start_code : 1) : 0);
    seq_put_decimal_ull(m, ' ', mm ? (permitted ? mm->end_code : 1) : 0);
    seq_put_decimal_ull(m, ' ', (permitted && mm) ? mm->start_stack : 0);
    seq_put_decimal_ull(m, ' ', esp);
    seq_put_decimal_ull(m, ' ', eip);
    /* The signal information here is obsolete.
     * It must be decimal for Linux 2.0 compatibility.
     * Use /proc/#/status for real-time signals.
     */
    seq_put_decimal_ull(m, ' ', task->pending.signal.sig[0] & 0x7fffffffUL);
    seq_put_decimal_ull(m, ' ', task->blocked.sig[0] & 0x7fffffffUL);
    seq_put_decimal_ull(m, ' ', sigign.sig[0] & 0x7fffffffUL);
    seq_put_decimal_ull(m, ' ', sigcatch.sig[0] & 0x7fffffffUL);
    seq_put_decimal_ull(m, ' ', wchan);
    seq_put_decimal_ull(m, ' ', 0);
    seq_put_decimal_ull(m, ' ', 0);
    seq_put_decimal_ll(m, ' ', task->exit_signal);
    seq_put_decimal_ll(m, ' ', task_cpu(task));
    seq_put_decimal_ull(m, ' ', task->rt_priority);
    seq_put_decimal_ull(m, ' ', task->policy);
...
    seq_putc(m, '
');
    if (mm)
        mmput(mm);
    return 0;
}

2.3.3.2 bootchart中进程状态解释

在bootchart中显示的进程状态是从每个进程的/proc/x/stat中获取并解析的。

def draw_process_bar_chart(ctx, clip, options, proc_tree, times, curr_y, w, h, sec_w):
    header_size = 0
    if not options.kernel_only:
        draw_legend_box (ctx, "Running (%cpu)", PROC_COLOR_R, off_x    , curr_y + 45, leg_s)
        draw_legend_box (ctx, "Unint.sleep (I/O)", PROC_COLOR_D, off_x+120, curr_y + 45, leg_s)
        draw_legend_box (ctx, "Sleeping", PROC_COLOR_S, off_x+240, curr_y + 45, leg_s)
        draw_legend_box (ctx, "Zombie", PROC_COLOR_Z, off_x+360, curr_y + 45, leg_s)

从/proc/x/stat中看到的状态为单字符“RSDTtZXxKW”。

这些字符和内核中task_struct->state的对应关系，可以通过如下代码确定。

static const char * const task_state_array[] = {
    "R (running)",        /*   0 */
    "S (sleeping)",        /*   1 */
    "D (disk sleep)",    /*   2 */
    "T (stopped)",        /*   4 */
    "t (tracing stop)",    /*   8 */
    "Z (zombie)",        /*  16 */
    "X (dead)",        /*  32 */
    "x (dead)",        /*  64 */
    "K (wakekill)",        /* 128 */
    "W (waking)",        /* 256 */
};

#define TASK_RUNNING        0
#define TASK_INTERRUPTIBLE    1
#define TASK_UNINTERRUPTIBLE    2
#define __TASK_STOPPED        4
#define __TASK_TRACED        8
/* in tsk->exit_state */
#define EXIT_ZOMBIE        16
#define EXIT_DEAD        32
/* in tsk->state again */
#define TASK_DEAD        64
#define TASK_WAKEKILL        128
#define TASK_WAKING        256
#define TASK_STATE_MAX        512

#define TASK_STATE_TO_CHAR_STR "RSDTtZXxKW"

所以他们之间的关系如下：  

Bootchart进程状态	proc状态	task_struct状态
Running	R	TASK_RUNNING
Unint.sleep(I/O)	D	TASK_UNINTERRUPTIBLE
Sleeping	S	TASK_INTERRUPTIBLE
Zombie	Z	EXIT_ZOMBIE

2.3.4 bootchart对内核log分析

基于dmesg文件，_parse_dmesg()函数进行分析。

终点定义为"Freeing init memory"；initcall起点为“calling”，终点为“initcall”。

2.3.5 bootchartd对meminfo分析

proc_meminfo.log如下，经过_parse_proc_meminfo_log()分析，主要提取MemTotal、MemFree、Buffers、Cached等数值。

然后在draw.py的render_charts()中绘制曲线。

MemTotal: 63436 kB
MemFree: 51572 kB
Buffers: 0 kB
Cached: 452 kB
SwapCached: 0 kB
...
SwapTotal: 0 kB
SwapFree: 0 kB
...

2.3.6 bootchart对CPU占用率分析

bootchart通过保存/proc/stat信息，来记录CPU的使用率问题。

cpu 0 0 140 16 0 0 0 0 0 0
cpu0 0 0 140 16 0 0 0 0 0 0
intr 42288 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 2 0 0 0 0 0 0 0 0 0 254 0 0 0 0 138 0 0 315 0 55 0 0 139 139 0 0 0 0 0 0 0 0 0 0 0 0 2639 0 0 0 0 0 0 0 0 0 93 0 0 0 0 0 0 0 0 0 0 0 0 0 0 105 0 0 534 0 0 0 54 0 0 0 37821 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
ctxt 10926
btime 946692305
processes 708
procs_running 2
procs_blocked 0
softirq 243 0 243 0 0 0 0 0 0 0 0

2.3.6.1 /proc/stat解析

这些信息通过内核的show_stat()获取，这里主要分析第一行数据，第一行数据是所有CPU的累加信息。

第一行的数据表示的是CPU总的使用情况，依次是：user nice system idle iowait irq softirq steal guest guest_nice。

这些数值的单位是jiffies，jiffies是内核中的一个全局变量，用来记录系统以来产生的节拍数。在Linux中，一个节拍大致可理解为操作系统进程调度的最小时间片。

这些数值的单位并不是jiffies，而是USER_HZ定义的单位。也即一单位为10ms。

# define USER_HZ    100        /* some user interfaces are */
# define CLOCKS_PER_SEC    (USER_HZ)       /* in "ticks" like times() */

user： 从系统开始累计到当前时刻，处于用户态的运行时间，包含nice值为负进程。

nice： 从系统启动开始累计到当前时刻，nice值不为负的进程所占用的CPU时间。

system： 从系统启动开始累计到当前时刻，处于核心态的运行时间，不包括中断时间。

idle： 从系统启动开始累计到当前时刻，除IO等待时间以外的其它等待时间

iowait： 从系统启动开始累计到当前时刻，IO等待时间

irq： 从系统启动开始累计到当前时刻，硬中断时间

softirq： 从系统启动开始累计到当前时刻，软中断时间

总的CPU时间=user+nice+system+idle+iowait+irq+softirq

在进行show_stat()分析之前，需要先了解kernel_cpustat和kernel_stat这两个数据结构，这两个数据结构对应的实例都是per-CPU的。

enum cpu_usage_stat {
    CPUTIME_USER,
    CPUTIME_NICE,
    CPUTIME_SYSTEM,
    CPUTIME_SOFTIRQ,
    CPUTIME_IRQ,
    CPUTIME_IDLE,
    CPUTIME_IOWAIT,
    CPUTIME_STEAL,
    CPUTIME_GUEST,
    CPUTIME_GUEST_NICE,
    NR_STATS,
};

struct kernel_cpustat {
    u64 cpustat[NR_STATS];
};

struct kernel_stat {
#ifndef CONFIG_GENERIC_HARDIRQS
       unsigned int irqs[NR_IRQS];
#endif
    unsigned long irqs_sum;
    unsigned int softirqs[NR_SOFTIRQS];
};

内核中tick中断处理函数中调用update_process_times()进行stat更新。

void update_process_times(int user_tick)
{
    struct task_struct *p = current;
    int cpu = smp_processor_id();

    account_process_tick(p, user_tick);
...
}

void account_process_tick(struct task_struct *p, int user_tick)
{
    cputime_t one_jiffy_scaled = cputime_to_scaled(cputime_one_jiffy);
    struct rq *rq = this_rq();

    if (sched_clock_irqtime) {
        irqtime_account_process_tick(p, user_tick, rq);--------------------如果irq时间需要统计，使用此函数。
        return;
    }

    if (steal_account_process_tick())--------------------------------------累积到CPUTIME_STEAL。
        return;

    if (user_tick)---------------------------------------------------------处于用户态，更新用户态统计信息。
        account_user_time(p, cputime_one_jiffy, one_jiffy_scaled);
    else if ((p != rq->idle) || (irq_count() != HARDIRQ_OFFSET))-----------非用户态，则处于内核态；此处统计非idle，或者
        account_system_time(p, HARDIRQ_OFFSET, cputime_one_jiffy,
                    one_jiffy_scaled);
    else
        account_idle_time(cputime_one_jiffy);------------------------------idle状态时间。
}

void account_user_time(struct task_struct *p, cputime_t cputime,
               cputime_t cputime_scaled)
{
    int index;

    /* Add user time to process. */
    p->utime += cputime;
    p->utimescaled += cputime_scaled;
    account_group_user_time(p, cputime);

    index = (TASK_NICE(p) > 0) ? CPUTIME_NICE : CPUTIME_USER;---------------nice大于0的进程，累积到CPUTIME_NICE；nice小于等于的进程，累积到CPUTIME_USER。

    /* Add user time to cpustat. */
    task_group_account_field(p, index, (__force u64) cputime);

    /* Account for user time used */
    acct_update_integrals(p);
}

void account_system_time(struct task_struct *p, int hardirq_offset,
             cputime_t cputime, cputime_t cputime_scaled)
{
    int index;

    if ((p->flags & PF_VCPU) && (irq_count() - hardirq_offset == 0)) {-----虚拟化环境中，累积到CPUTIME_GUEST、CPUTIME_GUEST_NICE。
        account_guest_time(p, cputime, cputime_scaled);
        return;
    }

    if (hardirq_count() - hardirq_offset)----------------------------------硬件中断中，累积到CPUTIME_IRQ。
        index = CPUTIME_IRQ;
    else if (in_serving_softirq())-----------------------------------------表示处于软中断中，累积到CPUTIME_SOFTIRQ。
        index = CPUTIME_SOFTIRQ;
    else
        index = CPUTIME_SYSTEM;--------------------------------------------内核中非idle、硬中断、软中断情况，累积到CPUTIME_SYSTEM。

    __account_system_time(p, cputime, cputime_scaled, index);
}

void account_idle_time(cputime_t cputime)
{
    u64 *cpustat = kcpustat_this_cpu->cpustat;
    struct rq *rq = this_rq();

    if (atomic_read(&rq->nr_iowait) > 0)
        cpustat[CPUTIME_IOWAIT] += (__force u64) cputime;------------------表示当前状态处于io等待，时间累积到CPUTIME_IOWAIT。
    else
        cpustat[CPUTIME_IDLE] += (__force u64) cputime;--------------------处于idle状态时间，累积到CPUTIME_IDLE。
}

关于中断信息的统计，在执行中断和软中断中有相关接口。

在每次硬中断处理中，都会调用kstat_incr_irqs_this_cpu()更新per-cpu的统计变量kernel_stat->irqs_sum，同时也更新irq_desc->kstat_irqs变量。

在软中断处理函数handle_pending_softirqs()中，更新对应软中断计数kernel_stat->softirqs[]。

#define kstat_incr_irqs_this_cpu(irqno, DESC)        
do {                            
    __this_cpu_inc(*(DESC)->kstat_irqs);        
    __this_cpu_inc(kstat.irqs_sum);            
} while (0)


static void handle_pending_softirqs(u32 pending, int cpu, int need_rcu_bh_qs)
{
    struct softirq_action *h = softirq_vec;
    unsigned int prev_count = preempt_count();

    local_irq_enable();
    for ( ; pending; h++, pending >>= 1) {
...
        kstat_incr_softirqs_this_cpu(vec_nr);
...
    }
    local_irq_disable();
}


static inline unsigned int kstat_softirqs_cpu(unsigned int irq, int cpu)
{
       return kstat_cpu(cpu).softirqs[irq];
}

内核在tick中不停地更新统计数据，然后用户空间想要知道CPU占用率，只需要解析/proc/stat文件信息。

下面就看看/proc/stat对应的函数show_stat()。

static int show_stat(struct seq_file *p, void *v)
{
    int i, j;
    unsigned long jif;
    u64 user, nice, system, idle, iowait, irq, softirq, steal;
    u64 guest, guest_nice;
    u64 sum = 0;
    u64 sum_softirq = 0;
    unsigned int per_softirq_sums[NR_SOFTIRQS] = {0};
    struct timespec boottime;

    user = nice = system = idle = iowait =
        irq = softirq = steal = 0;
    guest = guest_nice = 0;
    getboottime(&boottime);
    jif = boottime.tv_sec;

    for_each_possible_cpu(i) {------------------------------------------遍历所有possible CPU的cpustat，做累加操作。综合所有CPU给出一个统计值。可以看出下面统计和cpu_usage_stat一一对应。
        user += kcpustat_cpu(i).cpustat[CPUTIME_USER];
        nice += kcpustat_cpu(i).cpustat[CPUTIME_NICE];
        system += kcpustat_cpu(i).cpustat[CPUTIME_SYSTEM];
        idle += get_idle_time(i);
        iowait += get_iowait_time(i);
        irq += kcpustat_cpu(i).cpustat[CPUTIME_IRQ];
        softirq += kcpustat_cpu(i).cpustat[CPUTIME_SOFTIRQ];
        steal += kcpustat_cpu(i).cpustat[CPUTIME_STEAL];
        guest += kcpustat_cpu(i).cpustat[CPUTIME_GUEST];
        guest_nice += kcpustat_cpu(i).cpustat[CPUTIME_GUEST_NICE];
        sum += kstat_cpu_irqs_sum(i);-----------------------------------从启动到现在的中断数目，kernel_stat->irqs_sum。
        sum += arch_irq_stat_cpu(i);

        for (j = 0; j < NR_SOFTIRQS; j++) {-----------------------------遍历所有的softirq。
            unsigned int softirq_stat = kstat_softirqs_cpu(j, i);-------从启动到现在的软中断数目，kernel_stat->softirqs[i]。

            per_softirq_sums[j] += softirq_stat;
            sum_softirq += softirq_stat;
        }
    }
    sum += arch_irq_stat();

    seq_puts(p, "cpu ");
    seq_put_decimal_ull(p, ' ', cputime64_to_clock_t(user));
    seq_put_decimal_ull(p, ' ', cputime64_to_clock_t(nice));
    seq_put_decimal_ull(p, ' ', cputime64_to_clock_t(system));
    seq_put_decimal_ull(p, ' ', cputime64_to_clock_t(idle));
    seq_put_decimal_ull(p, ' ', cputime64_to_clock_t(iowait));
    seq_put_decimal_ull(p, ' ', cputime64_to_clock_t(irq));
    seq_put_decimal_ull(p, ' ', cputime64_to_clock_t(softirq));
    seq_put_decimal_ull(p, ' ', cputime64_to_clock_t(steal));
    seq_put_decimal_ull(p, ' ', cputime64_to_clock_t(guest));
    seq_put_decimal_ull(p, ' ', cputime64_to_clock_t(guest_nice));
    seq_putc(p, '
');

    for_each_online_cpu(i) {-------------------------------------------下面分别处理CUP单核的统计信息。
        /* Copy values here to work around gcc-2.95.3, gcc-2.96 */
        user = kcpustat_cpu(i).cpustat[CPUTIME_USER];
        nice = kcpustat_cpu(i).cpustat[CPUTIME_NICE];
        system = kcpustat_cpu(i).cpustat[CPUTIME_SYSTEM];
        idle = get_idle_time(i);
        iowait = get_iowait_time(i);
        irq = kcpustat_cpu(i).cpustat[CPUTIME_IRQ];
        softirq = kcpustat_cpu(i).cpustat[CPUTIME_SOFTIRQ];
        steal = kcpustat_cpu(i).cpustat[CPUTIME_STEAL];
        guest = kcpustat_cpu(i).cpustat[CPUTIME_GUEST];
        guest_nice = kcpustat_cpu(i).cpustat[CPUTIME_GUEST_NICE];
        seq_printf(p, "cpu%d", i);
        seq_put_decimal_ull(p, ' ', cputime64_to_clock_t(user));
        seq_put_decimal_ull(p, ' ', cputime64_to_clock_t(nice));
        seq_put_decimal_ull(p, ' ', cputime64_to_clock_t(system));
        seq_put_decimal_ull(p, ' ', cputime64_to_clock_t(idle));
        seq_put_decimal_ull(p, ' ', cputime64_to_clock_t(iowait));
        seq_put_decimal_ull(p, ' ', cputime64_to_clock_t(irq));
        seq_put_decimal_ull(p, ' ', cputime64_to_clock_t(softirq));
        seq_put_decimal_ull(p, ' ', cputime64_to_clock_t(steal));
        seq_put_decimal_ull(p, ' ', cputime64_to_clock_t(guest));
        seq_put_decimal_ull(p, ' ', cputime64_to_clock_t(guest_nice));
        seq_putc(p, '
');
    }
    seq_printf(p, "intr %llu", (unsigned long long)sum);------------------所有CPU的硬中断计数。

    /* sum again ? it could be updated? */
    for_each_irq_nr(j)
        seq_put_decimal_ull(p, ' ', kstat_irqs_usr(j));-------------------再次遍历所有硬件中断描述符，打印中断执行次数。

    seq_printf(p,
        "
ctxt %llu
"
        "btime %lu
"
        "processes %lu
"
        "procs_running %lu
"
        "procs_blocked %lu
",
        nr_context_switches(),-------------------------------------------所有核的进程切换统计和。
        (unsigned long)jif,
        total_forks,
        nr_running(),----------------------------------------------------正在运行的进程数目。
        nr_iowait());----------------------------------------------------处于io等待状态的进程数目。

    seq_printf(p, "softirq %llu", (unsigned long long)sum_softirq);------所有软中断计数。

    for (i = 0; i < NR_SOFTIRQS; i++)
        seq_put_decimal_ull(p, ' ', per_softirq_sums[i]);----------------单个软中断计数，依次是HI_SOFTIRQ,TIMER_SOFTIRQ,NET_TX_SOFTIRQ,NET_RX_SOFTIRQ,BLOCK_SOFTIRQ,BLOCK_IOPOLL_SOFTIRQ,TASKLET_SOFTIRQ,SCHED_SOFTIRQ,HRTIMER_SOFTIRQ,RCU_SOFTIRQ。
    seq_putc(p, '
');

    return 0;
}

从_parse_proc_stat_log()可以看出，bootchart统计的时间。

由于/proc/stat是累加时间，所以下一次时间统计需要减去上次统计值。

在bootchart图表中，CPU=user+system，所以将内核时间分为三类，和内核时间的关系如下。

CPU=user+nice+system+irq+softirq，iowait=iowait，剩余部分为idle。因为都是tick为单位，所以这个占用率也是粗略的。

def _parse_proc_stat_log(file):
    samples = []
    ltimes = None
    for time, lines in _parse_timed_blocks(file):
        # skip emtpy lines
        if not lines:
            continue
        tokens = lines[0].split()
        if len(tokens) < 8:
            continue
        # CPU times {user, nice, system, idle, io_wait, irq, softirq}
        times = [ int(token) for token in tokens[1:] ]
        if ltimes:
            user = float((times[0] + times[1]) - (ltimes[0] + ltimes[1]))----------------------------------bootchart的user时间包括内核的user+nice
            system = float((times[2] + times[5] + times[6]) - (ltimes[2] + ltimes[5] + ltimes[6]))---------bootchart的system时间包括内核的system+irq+softirq
            idle = float(times[3] - ltimes[3])-------------------------------------------------------------bootchart的idle等于内核的idle
            iowait = float(times[4] - ltimes[4])-----------------------------------------------------------bootchart的iowait等于内核的iowait

            aSum = max(user + system + idle + iowait, 1)
            samples.append( CPUSample(time, us er/aSum, system/aSum, iowait/aSum) )

        ltimes = times
        # skip the rest of statistics lines
    return samples

2.4 测试结果分析

开机的时候bootchartd已经运行起来了，可以在shell中运行如下命令停止bootchartd。

bootchartd stop

在/var/log中生成bootlog.tgz文件，一个典型的bootlog.tgz包含如下文件。

 如下命令进入interactive模式，如果不带-i则生成一张png图片。

./pybootchartgui.py bootlog/bootlog.tgz --show-all -i

2.4.1 kernel boot

如果bootlog.tgz中包含了dmesg文件，就会生成k-boot相关信息。

可以很粗略的看出kernel boot占用的总时间，以及占用比较大的initcall。

更详细的initcall以阶梯形式在Kernel boot中展示，阶梯的长度和initcall时长成正比。

但这两种形式都不如bootgraph.html展示的更有效。

2.4.2 用户空间进程启动分析

下图可以分为5部分：

头信息：包含内核uname信息，内核command line。主要从header中获取。

CPU占用率：分为三部分CPU占用率、I/O占用率、剩下的是idle部分。主要从proc_stat.log中获取。

磁盘信息：磁盘的吞吐率和饱和度。主要从proc_diskstats.log中获取。

内存信息：分为5部分使用中、cached、buffer、swap以及剩余内存。主要从proc_meminfo.log中获取。

进程信息：包含进程的父子关系、启动时间、终止时间、运行状态等信息。主要从pro_ps.log中获取。

从下一张图可以看出主要问题在：

• 由于内核实时进程太多，导致rc启动延迟。
• internet.sh启动延迟太多。
• g_xxxx_trace_sy进程延迟问题。
• VpLoopThread延迟问题。

3. 总结

借助图形化的工具有利于发现问题，但解决问题还需要取具体问题具体对待。

Linux的启动从进入内核那一刻开始，到用户空间达到可用状态。

这个可用状态定义可能不一致，有的是进入shell，有的是弹出登陆框。但只要有一个固定的终点，就有了优化目标。

使用bootgraph.py进行优化，因为测试log本身会引入一些负荷，再找出问题点优化之后，关闭相关log。再和原始状态对比，比较准确。

在使用bootchart进行优化，需要根据实际情况适配采样时间。

如果采样率高，会导致额外负荷增加很多，因为CPU占用率、磁盘吞吐率、内存使用以及进程状态都是通过周期采样的得来的。

如果采样率太低，可能一些进程在采样周期内就启动-执行-退出了，不会被采样到。