【NUKE教程】Nuke Python 性能分析

20 九月, 2016
3
0

nukePerformance

使用性能计时器

在Nuke中打开性能计时器时,就可以通过Python读取性能信息。就能知道每个节点的运算时间。
在调试运行较慢的脚本,找出耗时瓶颈上很有帮助。

注意,打开性能计时器会影响Nuke的性能,因为会频繁打开、关闭计时器,同步线程。因此打开
此功能,Nuke会更慢,但是能让你获取nuke脚本处理时间的快照。

从命令行加上“-P” 会打开此功能,或者调用Python命令来打开计时器

	
nuke.startPerformanceTimers()

检查计时器是否允许性能计时器:

	
nuke.usingPerformanceTimers()

关闭计时器:

nuke.resetPerformanceTimers()

Nuke架构上的注意事项

当nuke内的节点要渲染时,有4个步骤:

  • store – 第一件事就是存下用户在knobs上选择的数据
  • validate – 节点告知Nuke其输出的信息,例如处理的哪个通道,以及大小
  • request – 在这节点弄明白了其需要哪些输入才能产生对应的输出(例如,需要通道,需要区域)
  • engine – 在这节点干了大部分的工作,并输出。这也是花费时间最多的地方。

更多信息,请看nuke 开发文档

 

通过python获取能耗时间

Nuke的性能计时器收集这四个处理阶段的信息,并可以通过python来获取。另外,性能计时器激活时,
计时信息会显示在节点图中。节点也会根据耗时比重显示不同的颜色,从绿(最快)到红(最慢)。

函数nuke.node.performanceInfo()会打印某个节点的时间信息。例如,下面的代码段就能
打印当前节点树种每个节点的时间信息(包括在 组内的节点):

for n in nuke.allNodes(recurseGroups=True):
    print n.fullName()
    print n.performanceInfo()

对一个简单的只有 Checkerboard-> Blur -> Defocus -> Viewer 的节点树输出和下面的很像:

Defocus1
{'callCount': 10228, 'timeTakenWall': 28524348, 'timeTakenCPU': 624512794}
Blur1
{'callCount': 9607, 'timeTakenWall': 9906815, 'timeTakenCPU': 151406143}
Viewer1
{'callCount': 0, 'timeTakenWall': 0, 'timeTakenCPU': 0}
CheckerBoard1
{'callCount': 34396, 'timeTakenWall': 3923322, 'timeTakenCPU': 29982254}

如上 nuke.Node.performanceInfo()返回了一个包含下列性能统计信息的字典:

  • callCount 这个过程被调用的次数
  • timeTakenWall 用墙上挂钟记录所花费的时间,用户实际要等待此处理要结束的时间。以毫秒计算。
  • timeTakenCPU
  • Linux上是CPU执行代码的时间,也是毫秒计时。是所有CPU上的用时总和。例如,多线程engine
    的处理时间就要比实际用时长很多。如果平均CPU时间(timeTakenCPU初始使用的线程数)比每个线程执行
    时间短,说明CPU线程花了很长时间但没有执行代码。例如,等待锁,说明性能又问题。
  • MAC和Win上,CPU时间还不能用,Mac上这个值和处理的总时间差不多。

在Linux Nuke开24线程上获取的时间信息,我们看下最耗时的两个节点Blur和Defocus:

Defocus1
{'callCount': 10228, 'timeTakenWall': 28524348, 'timeTakenCPU': 624512794}
Blur1
{'callCount': 9607, 'timeTakenWall': 9906815, 'timeTakenCPU': 151406143}

Blur节点的CPU时间是 wall time的24倍,Defocus节点的CPU时间是我们期望值的三分之二。说明engine的线程
都被Blur节点占用了,同事Defoucs节点花费了相当长的时间来等待,同时我们也发现了以后优化Nuke的一个方向!

其他性能统计

默认,nuke.Node.performanceInfo()会给出engine处理部分,通常也是最好是部分的用时信息. 也可以
通过传入下面的参数获取其他处理部分的用时信息:

nuke.PROFILE_STORE
nuke.PROFILE_VALIDATE
nuke.PROFILE_REQUEST
nuke.PROFILE_ENGINE

例如,获取Defocus节点在上面的数中的所有用时,可以用下面的代码:

n = nuke.toNode("Defocus1")
print "Defocus1"
print "Store"
print n.performanceInfo(nuke.PROFILE_STORE)
print "Validate"
print n.performanceInfo(nuke.PROFILE_VALIDATE)
print "Request"
print n.performanceInfo(nuke.PROFILE_REQUEST)
print "Engine"
print n.performanceInfo(nuke.PROFILE_ENGINE)

结果如下:

# Result: Defocus1
Store
{'callCount': 108, 'timeTakenWall': 6571, 'timeTakenCPU': 6563}
Validate
{'callCount': 53, 'timeTakenWall': 1451, 'timeTakenCPU': 1445}
Request
{'callCount': 108, 'timeTakenWall': 1017, 'timeTakenCPU': 1009}
Engine
{'callCount': 10228, 'timeTakenWall': 28524348, 'timeTakenCPU': 624512794}

正如预料的,Defocus大部分时间花在了engine处理上,store,validate,request相对都很快.
如果并非如此,或者callCount显示store,validate,request调用次数很多,就说明这
是一个影响性能的问题了.

注意某些节点就是要比例子中的Defocus在store,validate,request阶段花费更多时间.例如,
reader在validate阶段更长,因为需要打开文件,如果是网络文件就会更慢. ScanlineReader节点
是另一个例子,validate要更长,同事store节点比RotoPaint更慢,因为需要bake曲线.带有耗时
表达式的knbo也会在store节点花费更多时间.

性能信息写入XML

当使用 “-Pf “参数运行nuke时,性能数据连带部分系统数据会自动写入XML文件.
此模式下,性能计时器会再渲染开始前启动,渲染结束后就讲数据写入xml文件. 当nuke在
此模式运行时,调用:

	
nuke.performanceProfileFilename()

会返回xml文件名。