latencytop深度了解你的Linux系统的延迟

from: http://rdc.taobao.com/blog/cs/?p=893

我们在系统调优或者定位问题的时候，经常会发现多线程程序的效率很低，但是又不知道问题出在哪里，就知道上下文切换很多，但是为什么上下文切换，是谁导致切换，我们就不知道了。上下文切换可以用dstat这样的工具查看，比如：
[shell]
$dstat
—-total-cpu-usage—- -dsk/total- -net/total- —paging– —system–
usr sys idl wai hiq siq| read writ| recv send| in out | int csw
9 2 87 2 0 1|7398k 31M| 0 0 | 9.8k 11k| 16k 64k
20 4 69 3 0 4| 26M 56M| 34M 172M| 0 0 | 61k 200k
21 5 64 6 0 3| 26M 225M| 35M 175M| 0 0 | 75k 216k
21 5 66 4 0 4| 25M 119M| 34M 173M| 0 0 | 66k 207k
19 4 68 5 0 3| 23M 56M| 33M 166M| 0 0 | 60k 197k

#或者用systemtap脚本来看
$sudo stap -e ‘global cnt; probe scheduler.cpu_on {cnt<<<1;} probe timer.s(1){printf("%d\n", @count(cnt)); delete cnt;}'
217779
234141
234759
[/shell]

每秒高达200k左右的的上下文切换， 谁能告诉我发生了什么? 好吧，latencytop来救助了!

它的官网：http://www.latencytop.org/

Skipping audio, slower servers, everyone knows the symptoms of latency. But to know what’s going on in the system, what’s causing the latency, how to fix it… that’s a hard question without good answers right now.

LatencyTOP is a Linux* tool for software developers (both kernel and userspace), aimed at identifying where in the system latency is happening, and what kind of operation/action is causing the latency to happen so that the code can be changed to avoid the worst latency hiccups.

它是Intel贡献的另外一个性能查看器，还有一个是powertop ,都是很不错的工具.

Latencytop通过在内核上下文切换的时候，记录被切换的进程的内核栈，然后通过匹配内核栈的函数来判断是什么原因导致上下文切换，同时他把几十种容易引起切换的场景的函数都记录起来，这样在判断系统问题的时候能容易定位到问题。

latencytop分成2个部分，内核部分和应用部分。内核部分负责调用栈的收集并且通过/proc来暴露， 应用部分负责显示.

工作界面截图如下:

latencytop在2.6.256后被内核吸收成为其中一部分，只要编译的时候打开该选项就好，如何确认呢？
[shell]
$ cat /proc/latency_stats
Latency Top version : v0.1
[/shell]
看到这个就好了, 遗憾的是RHEL6竟然带了latencytop应用部分，而没有打开编译选项，让我们情何以堪呢？
在ubuntu下可以这么安装：

[shell]
$ uname -r
2.6.38-yufeng
$ apt-get install latencytop
$ sudo latencytop #就可以使用了
[/shell]

但是latencytop比较傻的是默认是开图像界面的，我们很不习惯，我们要文本界面, 自己动手把!

[shell]
$ apt-get source latencytop
$ diff -up Makefile.orig Makefile
— Makefile.orig 2011-03-29 20:10:29.025845447 +0800
+++ Makefile 2011-03-28 14:48:11.232318002 +0800
@@ -1,5 +1,5 @@
# FIXME: Use autoconf ?
-HAS_GTK_GUI = 0
+#HAS_GTK_GUI = 0

DESTDIR =
SBINDIR = /usr/sbin
[/shell]

重新make下就好了, 文本界面出现了. 具体使用参看 man latencytop。

fcicq同学说：

加个 –nogui 参数就好了. 不需要重新编译.

谢谢！

好了,那么latencytop支持多少种的延迟原因呢？让latencytop.trans告诉你，我们也可以自己修改这个文件，把新的延迟原因加上去。

[shell]
$ cat /usr/share/latencytop/latencytop.trans
#
1 vfs_read Reading from file
1 vfs_write Writing to file
1 __mark_inode_dirty Marking inode dirty
1 vfs_readdir Reading directory content
1 vfs_unlink Unlinking file
1 blocking_notifier_call_chain Blocking notifier
1 lock_super Superblock lock contention
1 vfs_create Creating a file
1 KAS_ScheduleTimeout Binary AMD driver delay
1 firegl_lock_device Binary AMD driver delay
#
2 __bread Synchronous buffer read
2 do_generic_mapping_read Reading file data
2 sock_sendmsg Sending data over socket
2 do_sys_open Opening file
2 do_sys_poll Waiting for event (poll)
2 core_sys_select Waiting for event (select)
2 proc_reg_read Reading from /proc file
2 __pollwait Waiting for event (poll)
2 sys_fcntl FCNTL system call
2 scsi_error_handler SCSI error handler
2 proc_root_readdir Reading /proc directory
2 ksoftirqd Waking ksoftirqd
2 worker_thread .
2 do_unlinkat Unlinking file
2 __wait_on_buffer Waiting for buffer IO to complete
2 pdflush pdflush() kernel thread
2 kjournald kjournald() kernel thread
2 blkdev_ioctl block device IOCTL
2 kauditd_thread kernel audit daemon
2 tty_ioctl TTY IOCTL
2 __filemap_fdatawrite_range fdatasync system call
2 do_sync_write synchronous write
2 kthreadd kthreadd kernel thread
2 usb_port_resume Waking up USB device
2 usb_autoresume_device Waking up USB device
2 kswapd kswapd() kernel thread
2 md_thread Raid resync kernel thread
2 i915_wait_request Waiting for GPU command to complete
2 request_module Loading a kernel module

#
3 tty_wait_until_sent Waiting for TTY to finish sending
3 pipe_read Reading from a pipe
3 pipe_write Writing to a pipe
3 pipe_wait Waiting for pipe data
3 read_block_bitmap Reading EXT3 block bitmaps
3 scsi_execute_req Executing raw SCSI command
3 sys_wait4 Waiting for a process to die
3 sr_media_change Checking for media change
3 sr_do_ioctl SCSI cdrom ioctl
3 sd_ioctl SCSI disk ioctl
3 sr_cd_check Checking CDROM media present
3 ext3_read_inode Reading EXT3 inode
3 htree_dirblock_to_tree Reading EXT3 directory htree
3 ext3_readdir Reading EXT3 directory
3 ext3_bread Synchronous EXT3 read
3 ext3_free_branches Unlinking file on EXT3
3 ext3_get_branch Reading EXT3 indirect blocks
3 ext3_find_entry EXT3: Looking for file
3 __ext3_get_inode_loc Reading EXT3 inode
3 ext3_delete_inode EXT3 deleting inode
3 sync_page Writing a page to disk
3 tty_poll Waiting for TTY data
3 tty_read Waiting for TTY input
3 tty_write Writing data to TTY
3 update_atime Updating inode atime
3 page_cache_sync_readahead Pagecache sync readahead
3 do_fork Fork() system call
3 sys_mkdirat Creating directory
3 lookup_create Creating file
3 inet_sendmsg Sending TCP/IP data
3 tcp_recvmsg Receiving TCP/IP data
3 link_path_walk Following symlink
3 path_walk Walking directory tree
3 sys_getdents Reading directory content
3 unix_stream_recvmsg Waiting for data on unix socket
3 ext3_mkdir EXT3: Creating a directory
3 journal_get_write_access EXT3: Waiting for journal access
3 synchronize_rcu Waiting for RCU
3 input_close_device Closing input device
3 mousedev_close_device Closing mouse device
3 mousedev_release Closing mouse device
3 mousedev_open Opening mouse device
3 kmsg_read Reading from dmesg
3 sys_futex Userspace lock contention
3 do_futex Userspace lock contention
3 vt_waitactive vt_waitactive IOCTL
3 acquire_console_sem Waiting for console access
3 filp_close Closing a file
3 sync_inode (f)syncing an inode to disk
3 ata_exec_internal_sg Executing internal ATA command
3 writeback_inodes Writing back inodes
3 ext3_orphan_add EXT3 adding orphan
3 ext3_mark_inode_dirty EXT3 marking inode dirty
3 ext3_unlink EXT3 unlinking file
3 ext3_create EXT3 Creating a file
3 log_do_checkpoint EXT3 journal checkpoint
3 generic_delete_inode Deleting an inode
3 proc_delete_inode Removing /proc file
3 do_truncate Truncating file
3 sys_execve Executing a program
3 journal_commit_transaction EXT3: committing transaction
3 __stop_machine_run Freezing the kernel (for module load)
3 sys_munmap unmapping memory
3 sys_mmap mmaping memory
3 sync_buffer Writing buffer to disk (synchronous)
3 inotify_inode_queue_event Inotify event
3 proc_lookup Looking up /proc file
3 generic_make_request Creating block layer request
3 get_request_wait Creating block layer request
3 alloc_page_vma Allocating a VMA
#3 __d_lookup Looking up a dentry
3 blkdev_direct_IO Direct block device IO
3 sys_mprotect mprotect() system call
3 shrink_icache_memory reducing inode cache memory footprint
3 vfs_stat_fd stat() operation
3 cdrom_open opening cdrom device
3 sys_epoll_wait Waiting for event (epoll)
3 sync_sb_inodes Syncing inodes
3 tcp_connect TCP/IP connect
3 ata_scsi_ioctl ATA/SCSI disk ioctl
3 do_rmdir Removing directory
3 vfs_rmdir Removing directory
3 sys_flock flock() on a file
3 usbdev_open opening USB device
3 lock_kernel Big Kernel Lock contention
3 blk_execute_rq Submitting block IO
3 scsi_cmd_ioctl SCSI ioctl command
3 acpi_ec_transaction ACPI hardware access
3 journal_get_undo_access Waiting for EXT3 journal undo operation
3 i915_irq_wait Waiting for GPU interrupt
3 i915_gem_throttle_ioctl Throttling GPU while waiting for commands

#
#
5 do_page_fault Page fault
5 handle_mm_fault Page fault
5 filemap_fault Page fault
5 sync_filesystems Syncing filesystem
5 sys_nanosleep Application requested delay
5 sys_pause Application requested delay
5 evdev_read Reading keyboard/mouse input
5 do_fsync fsync() on a file (type ‘F’ for details)
5 __log_wait_for_space Waiting for EXT3 journal space
[/shell]
延迟原因非常的详细.

本来到这里,我要介绍的要介绍了,但是且慢,由于这个东西要在2.6.26后的系统上使用,我们的线上系统大部分是RHEL 5U4, 2.6.18的, 我们如何使用呢?

这时候 systemtap 一如既往的前来救助了!

systemtap 1.4版本以后带了个latencytop.stp, 也是intel的贡献. 那我们试验下穷人家的latencytop.
它在那里呢?
[shell]
$ uname -r
2.6.18-164.el5

$ stap -V
Systemtap translator/driver (version 1.5 /0.137 non-git sources)
Copyright (C) 2005-2011 Red Hat, Inc. and others
This is free software; see the source for copying conditions.
enabled features: AVAHI LIBRPM LIBSQLITE3 NSS BOOST_SHARED_PTR TR1_UNORDERED_MAP NLS

$ ls -al /usr/share/doc/systemtap/examples/profiling/latencytap.stp
-rwxr-xr-x 1 chuba users 16240 Feb 17 22:02/usr/share/doc/systemtap/examples/profiling/latencytap.stp

$ sudo stap -t –all-modules /usr/share/doc/systemtap/examples/profiling/latencytap.stp
ERROR: Skipped too many probes, check MAXSKIPPED or try again with stap -t for more details.
WARNING: Number of errors: 0, skipped probes: 101
WARNING: Skipped due to global ‘dequeue’ lock timeout: 2
WARNING: Skipped due to global ‘this_sleep’ lock timeout: 99
—– probe hit report:
kernel.trace(“deactivate_task”)!, (/usr/share/doc/systemtap/examples/profiling/latencytap.stp:47:1), hits: 254, cycles: 680min/43327avg/2248467max, from: kernel.trace(“deactivate_task”)
kernel.trace(“activate_task”)!, (/usr/share/doc/systemtap/examples/profiling/latencytap.stp:58:1), hits: 255, cycles: 890min/502549avg/2271568max, from: kernel.trace(“activate_task”)
kernel.function(“finish_task_switch@kernel/sched.c:1969″)?, (/usr/share/doc/systemtap/examples/profiling/latencytap.stp:78:7), hits: 509, cycles: 213min/1002207avg/5382852max, from: kernel.function(“finish_task_switch”) from: scheduler.cpu_on
begin, (/usr/share/doc/systemtap/examples/profiling/latencytap.stp:123:1), hits: 1, cycles: 1802min/1802avg/1802max, from: begin
begin, (/usr/share/doc/systemtap/examples/profiling/latencytap.stp:131:1), hits: 1, cycles: 227979min/227979avg/227979max, from: begin
Pass 5: run failed. Try again with another ‘–vp 00001′ option.
[/shell]

出错了！ 原因是lock timeout, 原来stap的全局变量是用锁保护的，现在超时了！知道原因好办，打个patch吧！

[shell]
$ diff -up translate.cxx.orig translate.cxx
— translate.cxx.orig 2011-03-22 21:26:52.000000000 +0800
+++ /translate.cxx 2011-03-29 20:31:28.000000000 +0800
@@ -5802,10 +5802,10 @@ translate_pass (systemtap_session& s)
s.op->newline() << "#define MAXACTION_INTERRUPTIBLE (MAXACTION * 10)";
s.op->newline() << "#endif";
s.op->newline() << "#ifndef TRYLOCKDELAY";
- s.op->newline() << "#define TRYLOCKDELAY 10 /* microseconds */";
+ s.op->newline() << "#define TRYLOCKDELAY 50 /* microseconds */";
s.op->newline() << "#endif";
s.op->newline() << "#ifndef MAXTRYLOCK";
- s.op->newline() << "#define MAXTRYLOCK 100 /* 1 millisecond total */";
+ s.op->newline() << "#define MAXTRYLOCK 500 /* 1 millisecond total */";
s.op->newline() << "#endif";
s.op->newline() << "#ifndef MAXMAPENTRIES";
s.op->newline() << "#define MAXMAPENTRIES 2048";

#编译安装后再来一次
$ sudo stap --all-modules /usr/share/doc/systemtap/examples/profiling/latencytap.stp
ERROR: probe overhead exceeded threshold
WARNING: Number of errors: 1, skipped probes: 0
Pass 5: run failed. Try again with another '--vp 00001' option.

#又错了,这次原因是probe overhead exceeded threshold, 看下代码我们知道，脚本的开销太大了，超过正常的负载，通过查看代码可以用STP_NO_OVERLOAD来解除这个限制

#再来一次
$ sudo stap -DSTP_NO_OVERLOAD --all-modules -DMAXSKIPPED=1024 /usr/share/doc/systemtap/examples/profiling/latencytap.stp

Reason Count Average(us) Maximum(us) Percent%
Userspace lock contention 345 16409195 83258717 45%
1453 867513 60231852 10%
95 7391754 33821926 5%
migration() kernel thread 1733 402701 3571412 5%
7239 87993 401552 5%
Reading from a pipe 212 2922207 52151180 4%
142 2267850 17990214 2%
108 2457247 7494331 2%
Waking ksoftirqd 16 16082822 59266312 2%
Waiting for event (select) 99 2113310 28510974 1%
kjournald() kernel thread 148 1313447 13983084 1%
Application requested delay 94 1059898 10011409 0%
41 2391993 7618788 0%
Waiting for event (select) 38 2259444 29057362 0%
719 92947 584944 0%
Waiting for event (poll) 1 57582711 57582711 0%
Application requested delay 3 19030709 36000553 0%
Waiting for event (select) 39 1341880 5847683 0%
34 936628 6649350 0%
5 6163603 10008484 0%
...
[/shell]

这次看到结果了，哈哈，小高兴一把。但是在繁忙的系统上这个脚本的资源占用特别多，也是不爽的。 幸运的是这个脚本支持查看某个进程的延迟情况， 就是在 latencytap.stp 后面加个-x 参数。

这个脚本设计应该是支持进程ID, 但是结果写成了线程ID，属于bug！！！

动手改下吧：

[shell]
$ diff -u latencytap.stp.orig latencytap.stp
--- latencytap.stp.orig 2011-02-17 22:02:40.000000000 +0800
+++ latencytap.stp 2011-03-29 20:43:51.000000000 +0800
@@ -15,7 +15,7 @@
global this_sleep;
global debug = 0;

-function log_event:long (p:long) { return (!traced_pid || traced_pid == p) }
+function log_event:long (p:long) { return (!traced_pid || traced_pid == task_pid(p)) }

#func names from hex addresses
function func_backtrace:string (ips:string)
@@ -50,14 +50,14 @@
# check to see if task is in appropriate state:
# TASK_INTERRUPTIBLE 1
# TASK_UNINTERRUPTIBLE 2
- if (log_event($p->pid) && (s & 3)) {
+ if (log_event($p) && (s & 3)) {
dequeue[$p] = gettimeofday_us();
}
}

probe kernel.trace(“activate_task”) !,
kernel.function(“activate_task”) {
- if (!log_event($p->pid)) next
+ if (!log_event($p)) next

a = gettimeofday_us()
d = dequeue[$p]

#再来一次
$ sudo stap –all-modules /usr/share/doc/systemtap/examples/profiling/latencytap.stp -x $$
…
[/shell]

这下终于爽了，旧内核用systemtap版本的，新内核用内核版本的，世界和谐！

通过对线上MySQL的诊断发现大部分时间花在mutex锁的竞争上来，我说过了，我会收拾你的，等着瞧！

玩得开心！