Linux GNU time 评估程序性能表现

在开发完程序后可能需要对程序进行性能评估,比方说运行速度和内存占用在不同输入和参数情况下的表现。在 Linux 使用 GNU time 可以很轻松地测量到这些指标,为什么说 GNU time 呢?因为系统可能有 2 个 time 命令,一个是 shell 内置的,一个是 GNU time 命令,后者路径往往是 /usr/bin/time 可通过路径调用。

# shell 内置 time 
$ type time
time is a shell keyword

# GNU time
$ which time
/usr/bin/time

两个 time 命令的输入格式都是:

time [option ...] command [argument ...]

time 命令本身 + time 命令参数 + 要测量的命令(程序)及其参数。

直接调用 time 命令时可能会调用到 shell 内置的,建议使用 /usr/bin/time 路径调用。

# shell 内置 time 
$ time echo "just test"
just test

real    0m0.000s
user    0m0.000s
sys 0m0.000s

# GNU time
$ /usr/bin/time echo "just test"
just test
0.00user 0.00system 0:00.00elapsed 50%CPU (0avgtext+0avgdata 1792maxresident)k
0inputs+0outputs (0major+80minor)pagefaults 0swaps

GNU time 默认输出格式为:

%Uuser %Ssystem %Eelapsed %PCPU (%Xtext+%Ddata %Mmax)k
%Iinputs+%Ooutputs (%Fmajor+%Rminor)pagefaults %Wswaps

可通过 -f 参数修改输出格式,如:

$ /usr/bin/time -f "%e elapsed %E user" echo "just test"
just test
0.00 elapsed 0:00.00 user

使用 -v 参数报告所有统计信息,我一般是这么用的,因为一般 benchmark 都是要进行大量不同条件的测试,而且要有重复。不如输出所有统计保存到文件,再写个脚本去汇总统计。

$ /usr/bin/time -v echo "just test"
just test
    Command being timed: "echo just test"
    User time (seconds): 0.00
    System time (seconds): 0.00
    Percent of CPU this job got: 100%
    Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.00
    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): 1792
    Average resident set size (kbytes): 0
    Major (requiring I/O) page faults: 0
    Minor (reclaiming a frame) page faults: 81
    Voluntary context switches: 1
    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

其中 "Maximum resident set size" 指命令最大内存占用;"Elapsed (wall clock) time" 是命令现实的耗时;"User time" 和 "System time" 加起来是 CPU time。

内存占用多进程问题
如果使用多进程要注意最大内存占用是否是所有进程的加总,下面用一个测试脚本说明可能的问题,用 GNU time 测量结果与 psutil 测量结果进行比较。

将下面代码写入 MemoryTest.py 文件,代码定义一个 use_memory 函数会创建一个包含 1000000 随机浮点数的列表。然后分别测试使用和不使用多进程时最大内存占用。

import multiprocessing
import random
import time

def use_memory(i):
    random.seed(1001)
    random_list = [random.random() for _ in range(1000000)]
    time.sleep(10)
    return None

# 非多进程测试时使用
use_memory(0)

# 多进程测试时使用
with multiprocessing.Pool(4) as poool:
    poool.map(use_memory, range(4))

使用 time 命令测试不使用多进程的结果如下:

$ /usr/bin/time -f %M python MemoryTest.py 
403584

默认单位为 Kbytes。

使用多进程(4 进程)的结果:

$ /usr/bin/time -f %M python MemoryTest.py 
401632

两个结果相近,这不符合预期,莫非 time 只是测量一个子进程,没有给所有的加总处理?

作为对比,写一个 GetMemory.py 脚本,脚本里使用 psutil 每隔 1 秒对命令测量一次内存占用,并输出最大的占用值。

import psutil
import subprocess
import time

def peak_memory(process: psutil.Process) -> int:
    rss = process.memory_info().rss
    for child_process in process.children():
        rss += child_process.memory_info().rss
    return rss

if __name__ == "__main__":
    run_cmd = subprocess.Popen(["python", "MemoryTest.py"])
    process = psutil.Process(run_cmd.pid)

    max_memory = 0
    # 只要 MemoryTest.py 没结束就每隔 1 秒钟测量一次内存占用
    while run_cmd.poll() is None:
        each_memory = peak_memory(process)
        if each_memory > max_memory:
            max_memory = each_memory
        time.sleep(1)
    
    print(f"Peak Memory (Kbytes): {int(max_memory / 1024)}")

脚本使用 poll 函数检测命令是否完成,不使用 psutilis_running 函数,因为在 while 循环使用后者,会导致命令完成后由于主程序未接受退出状态并处理,命令变成 zombie 状态。由于 psutil.Process 是跟 pid 绑定的,而系统 pid 是会被重复使用的,所以用这个模块要注意操作。

使用 psutil 测量时,不使用多进程结果:

$ python GetMemory.py 
Peak Memory (Kbytes): 403712

跟之前使用 time 测量结果相近。

使用多进程结果:

$ python GetMemory.py 
Peak Memory (Kbytes): 1620840

大小约是不使用多进程的 4 倍,这也是设置的进程数,看起来是合理的。

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 204,684评论 6 478
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 87,143评论 2 381
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 151,214评论 0 337
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,788评论 1 277
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,796评论 5 368
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,665评论 1 281
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 38,027评论 3 399
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,679评论 0 258
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 41,346评论 1 299
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,664评论 2 321
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,766评论 1 331
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,412评论 4 321
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 39,015评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,974评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,203评论 1 260
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 45,073评论 2 350
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,501评论 2 343

推荐阅读更多精彩内容