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

我们在系统调优或者定位问题的时候，经常会发现多线程程序的效率很低，但是又不知道问题出在哪里，就知道上下文切换很多，但是为什么上下文切换，是谁导致切换，我们就不知道了。上下文切换可以用dstat这样的工具查看，比如：

$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

每秒高达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后被内核吸收成为其中一部分，只要编译的时候打开该选项就好，如何确认呢？

$ cat /proc/latency_stats
Latency Top version : v0.1

看到这个就好了, 遗憾的是RHEL6竟然带了latencytop应用部分，而没有打开编译选项，让我们情何以堪呢？
在ubuntu下可以这么安装：

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

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

$ 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

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

fcicq同学说：

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

谢谢！

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

$ 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

延迟原因非常的详细.

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

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

systemtap 1.4版本以后带了个latencytop.stp, 也是intel的贡献. 那我们试验下穷人家的latencytop.
它在那里呢?

$ 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.

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

$ 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%
...

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

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

动手改下吧：

$ 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 $$
...

#如果发现出来的Reason是空行， 就把latencytap.stp里面的debug=0, 改成debug=1

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

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

玩得开心！