關鍵詞：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\n", 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\n", 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\n", 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('\r\n', '') # 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...\n", 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\n" (using first value) */ G.jiffy_line[len] = '\0'; p = strchr(G.jiffy_line, '.'); if (!p) goto wait_more; while (isdigit(*++p)) p[-1] = *p; p[-1] = '\n'; p[0] = '\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] = '\0'; p = strchrnul(stat_line, '\n'); *p++ = '\n'; *p = '\0'; fputs(stat_line, fp);----------------------------------------------保存讀取的/proc/xxx/stat到fp中 if (!look_for_login_process) continue; ... } } closedir(dir); fputc('\n', 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\n", prog); fputs("version = "BC_VERSION_STR"\n", 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)\n", 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\n", 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 "\n" */ 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, '\n'); 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, '\n'); 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, '\n'); } 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, "\nctxt %llu\n" "btime %lu\n" "processes %lu\n" "procs_running %lu\n" "procs_blocked %lu\n", 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, '\n'); 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占用率、磁盤吞吐率、內存使用以及進程狀態都是通過周期采樣的得來的。
如果采樣率太低，可能一些進程在采樣周期內就啟動-執行-退出了，不會被采樣到。