time – 测定一个命令的资源使用情况

整理自:http://codingstandards.iteye.com/blog/798788

1. 用途说明

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的统计数据,请看后文慢慢道来。

2. 常用参数

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

time <command> [<arguments...>]

在命令执行完成之后就会打印出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参数可以只打印时间数值(秒数),不打印单位。



3. Linux time量测指令执行时间命令详解

指令名称: time
  
  使用权限: 所有使用者 
  使用方式: time [options] COMMAND [arguments]  
  说明: time 指令的用途,在于量测特定指令执行时所需消耗的时间及系统资源等资讯。例如 CPU 时间、记忆体、输入输出等等。需要特别注意的是,部分资讯在 Linux 上显示不出来。这是因为在 Linux 上部分资源的分配函式与 time 指令所预设的方式并不相同,以致于 time 指令无法取得这些资料。
  
  参数:  
  -o or --output=FILE
  设定结果输出档。这个选项会将 time 的输出写入 所指定的档案中。如果档案已经存在,系统将覆写其内容。
  -a or --append
  配合 -o 使用,会将结果写到档案的末端,而不会覆盖掉原来的内容。
  -f FORMAT or --format=FORMAT
  以 FORMAT 字串设定显示方式。当这个选项没有被设定的时候,会用系统预设的格式。不过你可以用环境变数 time 来设定这个格式,如此一来就不必每次登入系统都要设定一次。
  一般设定上,你可以用
   ' '
  表示跳栏,或者是用
   '
  '
  表示换行。每一项资料要用 % 做为前导。如果要在字串中使用百分比符号,就用 。(学过 C 语言的人大概会觉得很熟悉)
  time 指令可以显示的资源有四大项,分别是:
  
  Time resources
  Memory resources
  IO resources
  Command info
  
  详细的内容如下:
  
  Time Resources
  E 执行指令所花费的时间,格式是:[hour]:minute:second。请注意这个数字并不代表实际的 CPU 时间。
  e 执行指令所花费的时间,单位是秒。请注意这个数字并不代表实际的 CPU 时间。
  S 指令执行时在核心模式(kernel mode)所花费的时间,单位是秒。
  U 指令执行时在使用者模式(user mode)所花费的时间,单位是秒。
  P 执行指令时 CPU 的占用比例。其实这个数字就是核心模式加上使用者模式的 CPU 时间除以总时间。
  
  Memory Resources
  M 执行时所占用的实体记忆体的最大值。单位是 KB
  t 执行时所占用的实体记忆体的平均值,单位是 KB
  K 执行程序所占用的记忆体总量(stack+data+text)的平均大小,单位是 KB
  D 执行程序的自有资料区(unshared data area)的平均大小,单位是 KB
  p 执行程序的自有堆叠(unshared stack)的平均大小,单位是 KB
  X 执行程序间共享内容(shared text)的平均值,单位是 KB
  Z 系统记忆体页的大小,单位是 byte。对同一个系统来说这是个常数
  
  IO Resources
  F 此程序的主要记忆体页错误发生次数。所谓的主要记忆体页错误是指某一记忆体页已经置换到置换档(swap file)中,而且已经分配给其他程序。此时该页的内容必须从置换档里再读出来。
  R 此程序的次要记忆体页错误发生次数。所谓的次要记忆体页错误是指某一记忆体页虽然已经置换到置换档中,但尚未分配给其他程序。此时该页的内容并未被破坏,不必从置换档里读出来
  W 此程序被交换到置换档的次数
  c 此程序被强迫中断(像是分配到的 CPU 时间耗尽)的次数
  w 此程序自愿中断(像是在等待某一个 I/O 执行完毕,像是磁碟读取等等)的次数
  I 此程序所输入的档案数
  O 此程序所输出的档案数
  r 此程序所收到的 Socket Message
  s 此程序所送出的 Socket Message
  k 此程序所收到的信号 ( Signal )数量
  
  Command Info
  C 执行时的参数以及指令名称
  x 指令的结束代码 ( Exit Status )
  
  -p or --portability
  这个选项会自动把显示格式设定成为:
  real %e
  user %U
  sys %S
  这么做的目的是为了与 POSIX 规格相容。
  -v or --verbose
  这个选项会把所有程序中用到的资源通通列出来,不但如一般英文语句,还有说明。对不想花时间去熟习格式设定或是刚刚开始接触这个指令的人相当有用。
  
  范例:
  利用下面的指令
   time -v ps -aux
  
  我们可以获得执行 ps -aux 的结果和所花费的系统资源。如下面所列的资料:
   USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
  root 1 0.0 0.4 1096 472 ? S Apr19 0:04 init
  root 2 0.0 0.0 0 0 ? SW Apr19 0:00 [kflushd]
  root 3 0.0 0.0 0 0 ? SW Apr19 0:00 [kpiod]
  ......
  root 24269 0.0 1.0 2692 996 pts/3 R 12:16 0:00 ps -aux
  
   Command being timed: "ps -aux"
   User time (seconds): 0.05
   System time (seconds): 0.06
   Percent of CPU this job got: 68%
   Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.16
   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: 238
   Minor (reclaiming a frame) page faults: 46
   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



4. 使用示例

4.1 示例一 统计运行时间

[root@web186 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
[root@web186 root]#

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

[root@web186 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。
[root@web186 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参数时,直接打印所需时间的数值,单位为秒,而不是更友好的格式,包括分钟、秒钟的显示方式。
[root@web186 root]#

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

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

[root@web186 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内建命令经常会有意想不到的发现。

[root@web186 root]# type -a time
time is a shell keyword
time is /usr/bin/time

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

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

[root@web186 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 (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (154major+63minor)pagefaults 0swaps

注:注意后面两行,打印了很多信息,但看不太清楚。它有一个参数-v,可以打印得更清楚些。
[root@web186 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
[root@web186 root]#

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

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

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

[root@web186 root]# time find . -name "mysql.sh" >1.txt

real 0m0.081s
user 0m0.060s
sys 0m0.020s
[root@web186 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命令本身的输出并不会被重定向的。那现在怎么办呢?网上提供了两种解决方法【2,3】,我们一一尝试一下。

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

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

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

这次Bash认为命令都没有输入完成,少了分号。因为Bash认为后面的 } 是find命令的参数。
[root@web186 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
[root@web186 root]# cat 2.txt

real 0m0.068s
user 0m0.030s
sys 0m0.040s

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

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

[root@web186 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
[root@web186 root]# cat 2.txt

real 0m0.083s
user 0m0.040s
sys 0m0.020s
[root@web186 root]#

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

5. 问题思考

1. 为什么执行find命令的多次时间统计差别很大,一次实际时间需要12秒,另外几次却不足1秒?

linux time 指令

time 指令可以显示的资源有四大项,分别是:
Time resources
Memory resources
IO resources
Command info
详细的内容如下:

Time Resources
E 执行指令所花费的时间,格式是:[hour]:minute:second。请注意这个数字并不代表实际的 CPU 时间。
e 执行指令所花费的时间,单位是秒。请注意这个数字并不代表实际的 CPU 时间。
S 指令执行时在核心模式(kernel mode)所花费的时间,单位是秒。
U 指令执行时在使用者模式(user mode)所花费的时间,单位是秒。
P 执行指令时 CPU 的占用比例。其实这个数字就是核心模式加上使用者模式的 CPU 时间除以总时间。

Memory Resources
M 执行时所占用的实体记忆体的最大值。单位是 KB
t 执行时所占用的实体记忆体的平均值,单位是 KB
K 执行程序所占用的记忆体总量(stack+data+text)的平均大小,单位是 KB
D 执行程序的自有资料区(unshared data area)的平均大小,单位是 KB
p 执行程序的自有堆叠(unshared stack)的平均大小,单位是 KB
X 执行程序间共享内容(shared text)的平均值,单位是 KB
Z 系统记忆体页的大小,单位是 byte。对同一个系统来说这是个常数

IO Resources
F 此程序的主要记忆体页错误发生次数。所谓的主要记忆体页错误是指某一记忆体页已经置换到置换档(swap file)中,而且已经分配给其他程序。此时该页的内容必须从置换档里再读出来。
R 此程序的次要记忆体页错误发生次数。所谓的次要记忆体页错误是指某一记忆体页虽然已经置换到置换档中,但尚未分配给其他程序。此时该页的内容并未被破坏,不必从置换档里读出来
W 此程序被交换到置换档的次数
c 此程序被强迫中断(像是分配到的 CPU 时间耗尽)的次数
w 此程序自愿中断(像是在等待某一个 I/O 执行完毕,像是磁碟读取等等)的次数
I 此程序所输入的档案数
O 此程序所输出的档案数
r 此程序所收到的 Socket Message
s 此程序所送出的 Socket Message
k 此程序所收到的信号 ( Signal )数量

Command Info
C 执行时的参数以及指令名称
x 指令的结束代码 ( Exit Status )

-p or --portability
这个选项会自动把显示格式设定成为:
real %e
user %U
sys %S
这么做的目的是为了与 POSIX 规格相容。
-v or --verbose
这个选项会把所有程式中用到的资源通通列出来,不但如一般英文语句,还有说明。对不想花时间去熟习格式设定或是刚刚开始接触这个指令的人相当有用。
范例:
利用下面的指令
time -v ps -aux
我们可以获得执行 ps -aux 的结果和所花费的系统资源。如下面所列的资料:
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 1 0.0 0.4 1096 472 ? S Apr19 0:04 init
root 2 0.0 0.0 0 0 ? SW Apr19 0:00 [kflushd]
root 3 0.0 0.0 0 0 ? SW Apr19 0:00 [kpiod]
......
root 24269 0.0 1.0 2692 996 pts/3 R 12:16 0:00 ps -aux
Command being timed: "ps -aux"
User time (seconds): 0.05
System time (seconds): 0.06
Percent of CPU this job got: 68%
Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.16
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: 238
Minor (reclaiming a frame) page faults: 46
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

发表评论