Linux time命令如何详细记录并分析长时间运行程序的耗时与性能？

本文共计1786个文字，预计阅读时间需要8分钟。

“time命令功能监控与优化

time命令用于统计指定命令执行所耗费的总时间。

用法：time(参数)

参数指定需要统计时间的命令及其参数。

示例：测试一个程序或比较time命令的性能监控与优化。

time命令性能监测与优化​​time命令用于统计给定命令所花费的总时间。​​语法time(参数)参数指令指定需要运行的额指令及其参数。​​实例当测试一个程序或比较 time命令性能监测与优化  ​ ​time命令用于统计给定命令所花费的总时间。 ​ ​语法 time(参数) 参数 指令指定需要运行的额指令及其参数。  ​ ​实例 当测试一个程序或比较不同算法时执行时间是非常重要的一个好的算法应该是用时最短的。 ​ ​所有类UNIX系统都包含time命令使用这个命令可以统计时间消耗。 ​例如 ​ ​[rootlocalhost ~]# time ls  ​anaconda-ks.cfg  ​install.log  ​install.log.syslog  ​satools text  ​real 0m0.009s  ​user 0m0.002s  ​sys 0m0.007s  ​ ​输出的信息分别显示了该命令所花费的real时间、user时间和sys时间。  ​ ​real时间是指挂钟时间也就是命令开始执行到结束的时间。这个短时间包括其他进程所占用的时间片和进程被阻塞时所花费的时间。  ​ ​user时间是指进程花费在用户模式中的CPU时间这是唯一真正用于执行进程所花费的时间其他进程和花费阻塞状态中的时间没有计算在内。  ​ ​sys时间是指花费在内核模式中的CPU时间代表在内核中执系统调用所花费的时间这也是真正由进程使用的CPU时间。  ​ ​shell内建也有一个time命令当运行time时候是调用的系统内建命令应为系统内建的功能有限所以需要时间其他功能需要使用time命令可执行二进制文件/usr/bin/time。  ​ ​使用-o选项将执行时间写入到文件中  ​ ​/usr/bin/time -o outfile.txt ls  ​ ​使用-a选项追加信息  ​ ​/usr/bin/time -a -o outfile.txt ls  ​ ​使用-f选项格式化时间输出  ​ ​/usr/bin/time -f "time: %U" ls  ​ ​-f选项后的参数  ​参数 描述  ​%E real时间显示格式为[小时:]分钟:秒  ​%U user时间。  ​%S sys时间。  ​%C 进行计时的命令名称和命令行参数。  ​%D 进程非共享数据区域以KB为单位。  ​%x 命令退出状态。  ​%k 进程接收到的信号数量。  ​%w 进程被交换出主存的次数。  ​%Z 系统的页面大小这是一个系统常量不用系统中常量值也不同。  ​%P 进程所获取的CPU时间百分百这个值等于usersystem时间除以总共的运行时间。  ​%K 进程的平均总内存使用量datastacktext单位是KB。  ​%w 进程主动进行上下文切换的次数例如等待I/O操作完成。  ​%c 进程被迫进行上下文切换的次数由于时间片到期。 ​​

用途说明

time命令常用于测量一个命令的运行时间注意不是用来显示和修改系统时间的这是date命令干的事情。但是今天我通过查看time命令的手册页发现它能做的不仅仅是测量运行时间还可以测量内存、I/O等的使用情况手册页上的说法是time a simple command or give resource usage其中time一词我认为它应该是测量或测定的意思并不单指时间。一个程序在运行时使用的系统资源通常包括CPU、Memory和I/O等其中CPU资源的统计包括实际使用时间real time、用户态使用时间the process spent in user mode、内核态使用时间the process spent in kernel mode。但是简单的使用time命令并不能得到内存和I/O的统计数据请看后文慢慢道来。

常用参数

time命令最常用的使用方式就是在其后面直接跟上命令和参数

time []

在命令执行完成之后就会打印出CPU的使用情况

real    0m5.064s      < 实际使用时间real time user    0m0.020s     < 用户态使用时间the process spent in user mode sys     0m0.040s      < 内核态使用时间the process spent in kernel mode

time命令跟上-p参数可以只打印时间数值秒数不打印单位。

使用示例

示例一 统计运行时间

[rootweb186 root]# time find . -name "mysql.sh" ./work186/sms/bin/mysql.sh ./work186/sms/src/scripts/mysql.sh ./work186/sms/src/scripts1/mysql.sh ./work186/sms1/bin/mysql.sh ./work186/sms1/src/scripts/mysql.sh ./temp/sms/bin/mysql.sh ./temp/sms/src/scripts/mysql.sh real    0m14.837s user    0m0.030s sys     0m0.120s [rootweb186 root]#

注real远大于user加上sys因为find需要遍历各个目录需要大量的I/O操作而磁盘I/O通常是最慢的环节因此大部分时间find进程都在等待磁盘I/O完成。 ​

[rootweb186 root]# time find . -name "mysql.sh" ./work186/sms/bin/mysql.sh ./work186/sms/src/scripts/mysql.sh ./work186/sms/src/scripts1/mysql.sh ./work186/sms1/bin/mysql.sh ./work186/sms1/src/scripts/mysql.sh ./temp/sms/bin/mysql.sh ./temp/sms/src/scripts/mysql.sh real    0m0.230s user    0m0.040s sys     0m0.030s

注再次运行的时候发现real time变得很小了应该是操作系统将刚才操作过的一些文件缓存了的缘故因而大大减少了磁盘I/O。 ​ [rootweb186 root]# time -p find . -name "mysql.sh" ./work186/sms/bin/mysql.sh ./work186/sms/src/scripts/mysql.sh ./work186/sms/src/scripts1/mysql.sh ./work186/sms1/bin/mysql.sh ./work186/sms1/src/scripts/mysql.sh ./temp/sms/bin/mysql.sh ./temp/sms/src/scripts/mysql.sh real 0.15 user 0.04 sys 0.03

注使用-p参数时直接打印所需时间的数值单位为秒而不是更友好的格式包括分钟、秒钟的显示方式。 ​ [rootweb186 root]#

示例二 Linux系统中time命令其实不止一个

看过手册页的朋友会发现有个-f参数可以来指定统计信息的输出格式我们也来试一下。 ​

[rootweb186 root]# time -f "real %f\nuser %f\nsys %f\n" find . -name "mysql.sh"  ​ -bash: -f: command not found real    0m0.024s user    0m0.000s sys     0m0.000s

怪哉不灵啊。使用type -a来看一下。使用这个shell内建命令经常会有意想不到的发现。 ​

[rootweb186 root]# type -a time ​ time is a shell keyword time is /usr/bin/time

注通过这条命令我们可以发现我们常用的time其实是一个Shell关键字还有一个外部命令/usr/bin/time它有何不同呢 ​ [rootweb186 root]# /usr/bin/time ​ Usage: /usr/bin/time [-apvV] [-f format] [-o file] [--append] [--verbose]        [--portability] [--formatformat] [--outputfile] [--version]        [--help] command [arg...] ​

注外部命令/usr/bin/time功能更强大下面来尝试一下。 ​

[rootweb186 root]# /usr/bin/time find . -name "mysql.sh" ​ ./work186/sms/bin/mysql.sh ./work186/sms/src/scripts/mysql.sh ./work186/sms/src/scripts1/mysql.sh ./work186/sms1/bin/mysql.sh ./work186/sms1/src/scripts/mysql.sh ./temp/sms/bin/mysql.sh ./temp/sms/src/scripts/mysql.sh 0.03user 0.04system 0:00.12elapsed 55%CPU (0avgtext0avgdata 0maxresident)k 0inputs0outputs (154major63minor)pagefaults 0swaps ​

注注意后面两行打印了很多信息但看不太清楚。它有一个参数-v可以打印得更清楚些。 ​ [rootweb186 root]# /usr/bin/time -v find . -name "mysql.sh" ​ ./work186/sms/bin/mysql.sh ./work186/sms/src/scripts/mysql.sh ./work186/sms/src/scripts1/mysql.sh ./work186/sms1/bin/mysql.sh ./work186/sms1/src/scripts/mysql.sh ./temp/sms/bin/mysql.sh ./temp/sms/src/scripts/mysql.sh         Command being timed: "find . -name mysql.sh"         User time (seconds): 0.03         System time (seconds): 0.05         Percent of CPU this job got: 47%         Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.17         Average shared text size (kbytes): 0         Average unshared data size (kbytes): 0         Average stack size (kbytes): 0         Average total size (kbytes): 0         Maximum resident set size (kbytes): 0         Average resident set size (kbytes): 0         Major (requiring I/O) page faults: 153         Minor (reclaiming a frame) page faults: 64         Voluntary context switches: 0         Involuntary context switches: 0         Swaps: 0         File system inputs: 0         File system outputs: 0         Socket messages sent: 0         Socket messages received: 0         Signals delivered: 0         Page size (bytes): 4096         Exit status: 0 [rootweb186 root]#

尝试完这个之后我看了一下Google搜索的结果发现有位大虾早已发现了这个秘密见相关资料。 ​

示例三 解决time命令输出信息的重定向问题

time命令的输出信息是打印在标准错误输出上的 我们通过一个简单的尝试来验证一下。 ​

[rootweb186 root]# time find . -name "mysql.sh" >1.txt real    0m0.081s user    0m0.060s sys     0m0.020s [rootweb186 root]# time find . -name "mysql.sh" 2>2.txt ./work186/sms/bin/mysql.sh ./work186/sms/src/scripts/mysql.sh ./work186/sms/src/scripts1/mysql.sh ./work186/sms1/bin/mysql.sh ./work186/sms1/src/scripts/mysql.sh ./temp/sms/bin/mysql.sh ./temp/sms/src/scripts/mysql.sh real    0m0.068s user    0m0.040s sys     0m0.030s

通过上面的尝试发现无法将time的输出信息重定向到文件里面为什么因为time是shell的关键字shell做了特殊处理它会把time命令后面的命令行作为一个整体来进行处理在重定向时实际上是针对后面的命令来的time命令本身的输出并不会被重定向的。那现在怎么办呢网上提供了两种解决方法我们一一尝试一下。 ​

第一种解决方法就是将time命令和将要执行的命令行放到一个shell代码块中也就是一对大括号中要注意空格和分号的使用。 ​ [rootweb186 root]# {time find . -name "mysql.sh"} 2>2.txt

好像成功了。慢看一下对不对。 [rootweb186 root]# cat 2.txt -bash: {time: command not found

原来bash把 {time 作为一个整体来处理了前后都加上空格试试。 [rootweb186 root]# { time find . -name "mysql.sh" } 2>2.txt > CtrlC

这次Bash认为命令都没有输入完成少了分号。因为Bash认为后面的 } 是find命令的参数。 [rootweb186 root]# { time find . -name "mysql.sh"; } 2>2.txt ./work186/sms/bin/mysql.sh ./work186/sms/src/scripts/mysql.sh ./work186/sms/src/scripts1/mysql.sh ./work186/sms1/bin/mysql.sh ./work186/sms1/src/scripts/mysql.sh ./temp/sms/bin/mysql.sh ./temp/sms/src/scripts/mysql.sh [rootweb186 root]# cat 2.txt real    0m0.068s user    0m0.030s sys     0m0.040s

第一种方式的尝试成功了总结起来就是 { time command-line; } 2>file  注意分隔符的使用。 ​

另外一种方式就是使用子Shell的方式如下所示 ​

[rootweb186 root]# (time find . -name "mysql.sh") 2>2.txt ./work186/sms/bin/mysql.sh ./work186/sms/src/scripts/mysql.sh ./work186/sms/src/scripts1/mysql.sh ./work186/sms1/bin/mysql.sh ./work186/sms1/src/scripts/mysql.sh ./temp/sms/bin/mysql.sh ./temp/sms/src/scripts/mysql.sh [rootweb186 root]# cat 2.txt real    0m0.083s user    0m0.040s sys     0m0.020s [rootweb186 root]#

第二种方式的尝试也成功了总结起来就是 (time command-line) 2>file 这里time紧贴着小括号(也可以的命令行结束也不必带分号。当然最好还是用第一种方式毕竟启动一个子shell是要多占些资源的。

​