3. 性能分析 Profiling

概要

用 PETSc 的 -log_view 分析 Firedrake 程序的性能, 并由日志数据生成火焰图.

Overview

Profiling Firedrake programs with PETSc -log_view, and generating flame graphs from the log data.

Firedrake 程序的时间往往不是花在自己写的那几行代码里, 而是花在网格生成、 代码生成与编译、矩阵组装和线性方程组求解这些底层步骤上. Firedrake 建立在 PETSc 之上, 而 PETSc 自带一套性能日志: 它会记录每个内部步骤的调用次数、耗时和浮点运算数, 我们也可以用 PETSc.Log.Event 把自己关心的代码块标注成事件, 一并统计.

参考资料:

1. Optimising Firedrake performance: Firedrake 官方的性能优化指南, 讲火焰图的生成与解读、自定义事件的写法以及几个常见的性能问题, 是本章的主要依据.

2. PETSc: Profiling: PETSc 手册的性能分析一章. -log_view 的各种输出格式、输出表格每一列的含义都在这里.

3. PetscInitialize: PETSc 初始化阶段识别的命令行选项一览, 各个 -log_* 选项都列在其中.

4. PetscLogView: 把日志写到指定 viewer 的接口. 本章在 Notebook 中打印完整表格用的 PETSc.Log.view 就是它的 Python 版本.

The time a Firedrake program takes is usually not spent in the few lines one writes oneself, but in the underlying steps: mesh generation, code generation and compilation, matrix assembly and the solution of linear systems. Firedrake is built on PETSc, and PETSc comes with a performance log: it records the number of calls, the elapsed time and the number of floating-point operations of every internal step, and we can also mark the blocks of code we care about as events with PETSc.Log.Event so that they are counted as well.

References:

1. Optimising Firedrake performance: Firedrake’s official guide to performance optimization. It covers generating and reading flame graphs, how to write custom events and a few common performance problems; it is the main source for this chapter.

2. PETSc: Profiling: the profiling chapter of the PETSc manual. The output formats of -log_view and the meaning of every column of the output tables are described here.

3. PetscInitialize: a list of the command-line options recognized during PETSc initialization; all the -log_* options are among them.

4. PetscLogView: the interface that writes the log to a given viewer. PETSc.Log.view, used in this chapter to print the full table in the notebook, is its Python version.

3.1. log_view

-log_view 是 PETSc 的命令行选项, 加在脚本后面即可, 不需要改动代码:

-log_view is a PETSc command-line option; it is appended after the script name on the command line and requires no change to the code:

python3 your_script.py -log_view

程序结束时 PETSc 会把整个运行过程的性能摘要打印到标准输出. 冒号后面还可以指定输出文件和格式, 常用的几种是:

选项	作用
-log_view	把性能摘要打印到标准输出, 最常用
-log_view :profile.txt	同上, 但写入文件 profile.txt
-log_view :profile.txt:ascii_flamegraph	输出火焰图格式, 见下面的”火焰图”一节
-log_view :profile.xml:ascii_xml	输出为按调用关系嵌套的 XML
-log_view_memory	在事件表中额外给出内存分配的列

此外还有 -log_all (每个进程各写一个 Log.rank 文件)、-log_trace (实时打印每一步在做什么) 等选项, 完整列表见 PETSc 手册的 Profiling 一章.

When the program finishes, PETSc prints a performance summary of the whole run to standard output. An output file and a format can also be given after the colon; the common ones are:

Option	Effect
-log_view	print the performance summary to standard output, the most common one
-log_view :profile.txt	the same, but written to the file profile.txt
-log_view :profile.txt:ascii_flamegraph	output in flame graph format, see the section “Flame graphs” below
-log_view :profile.xml:ascii_xml	output as XML nested according to the call structure
-log_view_memory	add columns for memory allocation to the event table

There are further options such as -log_all (each process writes its own Log.rank file) and -log_trace (print what every step is doing in real time); for the full list see the Profiling chapter of the PETSc manual.

3.1.1. 读懂 -log_view 的输出 Reading the output of -log_view

-log_view 的输出分三段.

第一段是全局摘要, 给出整个运行过程的墙钟时间 Time (sec)、浮点运算总数 Flops、 MPI 消息条数和全局归约次数等. 每行有 Max、Max/Min、Avg、Total 四列, 分别是各进程上的最大值、最大值与最小值之比、平均值和总和. 其中 Max/Min 接近 1 说明各进程负载均衡, 这个比值越大负载越不均衡; 串行运行时非零量的比值恒为 1 (某一项本身为 0 时 PETSc 直接打成 0.0), 没有参考价值.

第二段 Summary of Stages 按阶段 (stage) 汇总. 不特意划分阶段时, 所有内容都记在 Main Stage 里.

第三段是事件表, 每个事件占一行, 既包括 KSPSolve、MatMult 这样的 PETSc 内部事件, 也包括自己用 PETSc.Log.Event 标注的事件. 主要几列的含义是:

• Count: 该事件被调用的次数, 和 Time/Flop 一样是最大值加最大最小比值;

• Time (sec): 各进程耗时的最大值, 后面跟着最大值与最小值之比;

• Flop: 浮点运算数, 同样是最大值加比值;

• Mess、AvgLen、Reduct: MPI 消息条数、平均消息长度 (字节) 和全局归约次数;

• %T %F %M %L %R: 该事件占总时间、总浮点运算数、总消息条数、总消息长度、总归约次数的百分比. --- Global --- 是相对整个程序, --- Stage ---- 是相对所在阶段;

• Mflop/s: 各进程浮点运算数之和除以最大耗时.

排查性能问题时, 通常先按 %T 找出最费时间的几项, 再看它们的 Mess/Reduct 和最大最小比值, 判断瓶颈是计算本身还是通信与负载不均衡. 并行情形下各列的详细解释见 Interpreting -log_view Output: Parallel Performance.

The output of -log_view has three parts.

The first part is a global summary giving the wall-clock time Time (sec), the total number of floating-point operations Flops, the number of MPI messages and the number of global reductions of the whole run. Every row has the four columns Max, Max/Min, Avg and Total: the maximum over the processes, the ratio of the maximum to the minimum, the average and the sum. A Max/Min close to 1 means the load is balanced across the processes, and the larger the ratio the worse the balance; in a serial run the ratio of every nonzero quantity is 1 (when a quantity is itself 0 PETSc simply prints 0.0), so it carries no information.

The second part, Summary of Stages, aggregates by stage. Unless stages are set up on purpose, everything is recorded in Main Stage.

The third part is the event table, one line per event, containing both PETSc’s internal events such as KSPSolve and MatMult and the events one marks oneself with PETSc.Log.Event. The main columns mean:

• Count: how many times the event was called; like Time/Flop it is the maximum followed by the max/min ratio;

• Time (sec): the maximum of the elapsed times over the processes, followed by the ratio of the maximum to the minimum;

• Flop: the number of floating-point operations, again the maximum followed by the ratio;

• Mess, AvgLen, Reduct: the number of MPI messages, the average message length (in bytes) and the number of global reductions;

• %T %F %M %L %R: the percentage of the total time, the total floating-point operations, the total number of messages, the total message length and the total number of reductions taken by this event. --- Global --- is relative to the whole program, --- Stage ---- relative to the stage it belongs to;

• Mflop/s: the sum of the floating-point operations over the processes divided by the maximum elapsed time.

When tracking down a performance problem one usually first picks out the most expensive items by %T, and then looks at their Mess/Reduct and max/min ratios to decide whether the bottleneck is the computation itself or communication and load imbalance. A detailed explanation of the columns in the parallel case is given in Interpreting -log_view Output: Parallel Performance.

3.1.2. 火焰图 Flame graphs

运行脚本时把选项换成 -log_view :profile.txt:ascii_flamegraph, PETSc 会把日志写成火焰图格式 (命令里的 py/profile_poisson.py 是本章最后一节”写成脚本运行”给出的脚本):

Replacing the option with -log_view :profile.txt:ascii_flamegraph when running a script makes PETSc write the log in flame graph format (the py/profile_poisson.py in the command is the script given in the last section of this chapter, “Running as a script”):

python3 py/profile_poisson.py -log_view :profile.txt:ascii_flamegraph

生成的 profile.txt 每行是一条调用栈和它的耗时 (单位是微秒), 形如

Every line of the resulting profile.txt is a call stack together with its elapsed time (in microseconds), of the form

Main Stage;firedrake;MyAssemble;firedrake.assemble.assemble;ParLoopExecute 288

把这个文件上传到在线工具 speedscope 就能看到火焰图; 也可以用 FlameGraph 提供的 flamegraph.pl 生成 SVG, 注意加上 --countname us, 否则鼠标悬停时显示的单位会写成 samples 而不是微秒. 火焰图比表格多出来的信息是事件之间的嵌套关系: Firedrake 自身的不少函数也带着事件装饰器, 因此能一眼看出时间是花在组装、代码编译还是求解上.

Uploading this file to the online tool speedscope shows the flame graph; alternatively flamegraph.pl from FlameGraph generates an SVG; note that --countname us should be added, otherwise the unit shown on hover reads samples instead of microseconds. What a flame graph adds over the table is the nesting of the events: many of Firedrake’s own functions carry event decorators too, so one can see at a glance whether the time goes into assembly, code compilation or the solve.

3.1.3. 自定义事件 Custom events

-log_view 默认只统计 PETSc 与 Firedrake 内部的事件. 用 PETSc.Log.Event 和 PETSc.Log.EventDecorator 可以把自己关心的代码块也标注成事件, 它的名字和运行时间会一并出现在上面的表格和火焰图中.

By default -log_view only accounts for the events internal to PETSc and Firedrake. With PETSc.Log.Event and PETSc.Log.EventDecorator the blocks of code we care about can be marked as events as well, and their names and run times then appear in the tables and flame graphs above.

1. PETSc.Log.Event 用作上下文管理器, 适合标注一段代码:PETSc.Log.Event is used as a context manager, suitable for marking a block of code:

   from firedrake.petsc import PETSc
   
   with PETSc.Log.Event("foo"):
       do_something_expensive()
   

2. PETSc.Log.EventDecorator 用作装饰器, 适合标注整个函数:PETSc.Log.EventDecorator is used as a decorator, suitable for marking a whole function:

   from firedrake.petsc import PETSc
   
   @PETSc.Log.EventDecorator("foo")
   def do_something_expensive():
       ...
   

   不传名字时, 事件名取”模块名.函数名”的形式. 事件表里的 firedrake.assemble.assemble 就是这么来的.Without a name, the event name takes the form “module name.function name”. This is where firedrake.assemble.assemble in the event table comes from.

事件名会原样出现在事件表的第一列, 而这一列的宽度是 16 个字符, 名字一旦超过 16 个字符, 这一行后面的所有列都会整体右移, 和表头对不齐, 因此事件名要尽量取短.

The event name appears verbatim in the first column of the event table, and that column is 16 characters wide; once a name exceeds 16 characters all the remaining columns of that line are shifted to the right and no longer line up with the header, so event names should be kept short.

3.2. 一个可运行的算例 A runnable example

对一个小规模的 Poisson 问题, 给网格生成、矩阵组装和线性求解分别加上自定义事件, 再把各事件的耗时读出来.

Notebook 里没有命令行, 加不了 -log_view, 所以要用 PETSc.Log.begin() 手动打开日志, 然后用事件对象的 getPerfInfo() 或 PETSc.Log.view 取结果. 需要火焰图或者其他命令行选项时, 仍然要把代码写成脚本运行, 见本节末尾.

For a small Poisson problem we attach custom events to the mesh generation, the matrix assembly and the linear solve, and then read off the elapsed time of each event.

A notebook has no command line, so -log_view cannot be passed; the log has to be turned on by hand with PETSc.Log.begin(), and the results are then obtained from the getPerfInfo() of the event objects or from PETSc.Log.view. For flame graphs or other command-line options the code still has to be run as a script, see the end of this section.

import petsctools
from firedrake.petsc import PETSc

# 命令行传了 -log_view 时 PETSc 已经自动开启日志, 此时不要再调用 Log.begin():
# 那会额外启动一个扁平日志处理器, 用 ascii_xml / ascii_flamegraph 这类嵌套格式时,
# 程序退出会报 "Trying to end paused event, not allowed".
if 'log_view' not in petsctools.get_commandline_options():
    PETSc.Log.begin()

t_start = PETSc.Log.getTime()   # 记下起点, 后面用来算耗时占比

print('logging active:', PETSc.Log.isActive())

logging active: True

petsctools.get_commandline_options() 返回 PETSc 从命令行认出的选项名. Notebook 的启动参数里没有 log_view, 于是 PETSc.Log.begin() 会被调用; 把同一段代码放进脚本并带上 -log_view 运行时, 这次调用会被跳过. 这个写法取自 Firedrake 文档的 Optimising 一节.

之所以要加这个判断: 传了 -log_view 时 PETSc 已经自己把日志开好了 (普通格式开的是扁平日志, :...:ascii_xml 和 :...:ascii_flamegraph 开的是嵌套日志), 这时再调用一次 PETSc.Log.begin() 会额外启动一个扁平日志处理器; 用后两种嵌套格式时, 程序退出时会报 Trying to end paused event, not allowed.

打开日志之后就可以正常写 Firedrake 代码了. 注意 PETSc.Log.begin() 必须放在被计时的代码之前, 在它之前发生的事情 (例如 import firedrake 本身) 不会被记录.

petsctools.get_commandline_options() returns the option names PETSc recognizes on the command line. The notebook is not started with log_view, so PETSc.Log.begin() is called; when the same code is put into a script and run with -log_view, this call is skipped. The idiom is taken from the Optimising section of the Firedrake documentation.

The reason for the test: when -log_view is given, PETSc has already turned the log on by itself (the plain format turns on a flat log, :...:ascii_xml and :...:ascii_flamegraph turn on a nested log), and calling PETSc.Log.begin() once more then starts an additional flat log handler; with the latter two nested formats the program reports Trying to end paused event, not allowed on exit.

Once the log is on, the Firedrake code is written as usual. Note that PETSc.Log.begin() must come before the code being timed; whatever happens before it (for example import firedrake itself) is not recorded.

from firedrake import *

N = 64
params = {'ksp_type': 'cg', 'pc_type': 'jacobi', 'ksp_rtol': 1e-10}

with PETSc.Log.Event('MyMesh'):
    mesh = UnitSquareMesh(N, N)
    V = FunctionSpace(mesh, 'CG', 1)

x, y = SpatialCoordinate(mesh)
u, v = TrialFunction(V), TestFunction(V)
a = inner(grad(u), grad(v))*dx
L = inner(sin(pi*x)*sin(pi*y), v)*dx
bc = DirichletBC(V, 0, 'on_boundary')
u_h = Function(V, name='u_h')

with PETSc.Log.Event('MyAssemble'):
    A = assemble(a, bcs=bc)
    b = assemble(L, bcs=bc)

with PETSc.Log.Event('MySolve'):
    solve(A, u_h, b, solver_parameters=params)

print('number of dofs:', V.dim())

number of dofs: 4225

这里把组装和求解拆成了两步 (先 assemble 得到矩阵 A 和右端项 b, 再解线性方程组), 这样两个事件的耗时才分得开; 直接写 solve(a == L, u_h, bcs=bc) 时, 组装是在求解内部完成的, 事件表里就只剩一个数.

PETSc.Log.Event(name) 用同一个名字再取一次, 拿到的还是同一个事件, 因此可以在事后用 getPerfInfo() 读出它的统计量: 一个字典, 含调用次数 count、累计耗时 time (秒)、浮点运算数 flops, 以及并行时才非零的 numMessages、messageLength、 numReductions.

Assembly and solve are split into two steps here (first assemble gives the matrix A and the right-hand side b, then the linear system is solved) so that the times of the two events can be told apart; written directly as solve(a == L, u_h, bcs=bc), the assembly is done inside the solve and only one number is left in the event table.

Asking for PETSc.Log.Event(name) again with the same name gives the same event, so its statistics can be read afterwards with getPerfInfo(): a dictionary containing the number of calls count, the accumulated time time (in seconds), the number of floating-point operations flops, and numMessages, messageLength, numReductions, which are nonzero only in parallel.

def show_events(names):
    """打印各事件的调用次数、累计耗时、耗时占比和浮点运算数."""
    elapsed = PETSc.Log.getTime() - t_start
    print('event'.ljust(14) + 'count'.rjust(6) + 'time (s)'.rjust(10)
          + '%T'.rjust(7) + 'flop'.rjust(12))
    for name in names:
        info = PETSc.Log.Event(name).getPerfInfo()
        count, t, flop = info['count'], info['time'], info['flops']
        print(f'{name:<14}{count:>6}{t:>10.4f}{100*t/elapsed:>6.1f}%{flop:>12.3e}')


show_events(['MyMesh', 'MyAssemble', 'MySolve'])

event          count  time (s)     %T        flop
MyMesh             1    0.2186  71.5%   0.000e+00
MyAssemble         1    0.0440  14.4%   3.635e+06
MySolve            1    0.0290   9.5%   1.125e+07

%T 一列是各事件耗时占 t_start 以来墙钟时间的比例. 它只是对 -log_view 同名列的粗略模仿: 分母里还包含 Notebook 单元之间的空闲时间, 交互式运行时等得越久这个比例越小, 因此看它的相对大小即可, 不必当作精确值.

具体的秒数取决于机器, 也取决于 Firedrake 的磁盘缓存是否预热, 但可以看出: 三个事件的耗时都远大于真正的线性代数运算 (后面完整表格里 KSPSolve 只有几毫秒). 原因是 Firedrake 会把变分形式即时编译成 C 代码 (JIT), 第一次组装和第一次求解都包含了代码生成、编译、稀疏结构构建和求解器 setup 这些一次性开销. 下面把同样的组装和求解再做一遍就能看出差别.

The %T column is the share of the elapsed time of each event in the wall-clock time since t_start. It is only a rough imitation of the column of the same name in -log_view: the denominator also contains the idle time between the notebook cells, so the longer one waits in interactive use the smaller this share becomes; so only its relative size is meaningful; it should not be taken as an exact value.

The actual number of seconds depends on the machine, and also on whether Firedrake’s disk cache is warm, but one can see that all three events take far longer than the linear algebra itself (KSPSolve in the full table below takes only a few milliseconds). The reason is that Firedrake compiles variational forms into C code just in time (JIT), so the first assembly and the first solve both include the one-off costs of code generation, compilation, building the sparsity pattern and solver setup. Doing the same assembly and solve once more below makes the difference visible.

with PETSc.Log.Event('MyAssemble2'):
    A = assemble(a, bcs=bc)
    b = assemble(L, bcs=bc)

u_h.assign(0)      # 让两次求解从同一个初值出发, 迭代步数才可比
with PETSc.Log.Event('MySolve2'):
    solve(A, u_h, b, solver_parameters=params)

show_events(['MyAssemble', 'MyAssemble2', 'MySolve', 'MySolve2'])

event          count  time (s)     %T        flop
MyAssemble         1    0.0440  13.5%   3.635e+06
MyAssemble2        1    0.0073   2.2%   3.635e+06
MySolve            1    0.0290   8.9%   1.125e+07
MySolve2           1    0.0083   2.5%   1.125e+07

两次组装的 flop 完全相同, 说明做的是同一件事, 但第二次的耗时低了一个数量级以上; 求解也是同样的情况. 由此有两条经验:

• 给自己的代码计时之前应当先”热身”, 即先跑一遍把编译和 setup 的开销排除掉, 否则测到的主要是编译时间;

• 反过来, 若程序只求解一次就结束, 那么编译开销确实是真实成本, 这时应当关注的是如何复用缓存, 而不是优化求解器.

Firedrake 会把编译好的代码缓存到磁盘, 因此同一段代码第二次运行时”第一次组装”也会比冷启动快. 冷热两种情形下上面的对比都成立, 只是差距大小不同.

The flop counts of the two assemblies are exactly the same, so they do the same work, but the second one takes more than an order of magnitude less time; the same happens for the solves. Two rules of thumb follow:

• before timing one’s own code one should “warm up” by running it once to get the compilation and setup costs out of the way, otherwise what is measured is mostly compilation time;

• conversely, if the program solves only once and then stops, the compilation cost is indeed a real cost, and what should be looked at then is how to reuse the cache rather than how to optimize the solver.

Firedrake caches the compiled code on disk, so on a second run of the same code even the “first assembly” is faster than from cold. The comparison above holds in both the cold and the warm case; only the size of the gap differs.

最后看完整的 -log_view 表格. PETSc.Log.view 接受一个 viewer, 不给参数时写到标准输出, 但那样会连同主机名、用户名一起打印出来, 因此这里把它写进一个临时文件, 再挑需要的行打印.

Finally we look at the full -log_view table. PETSc.Log.view takes a viewer and writes to standard output when called without one, but that would also print the host name and the user name, so here it is written to a temporary file from which only the required lines are printed.

import os
import tempfile

with tempfile.TemporaryDirectory() as tmpdir:
    filename = os.path.join(tmpdir, 'profile.txt')
    viewer = PETSc.Viewer().createASCII(filename, comm=COMM_WORLD)
    PETSc.Log.view(viewer)
    viewer.destroy()            # 先关闭再读, 确保内容已经写入文件
    with open(filename) as f:
        lines = f.read().splitlines()

summary = ('Time (sec):', 'Flops:', 'Event  ', '                   Max Ratio')
events = ('MyMesh', 'MyAssemble', 'MyAssemble2', 'MySolve', 'MySolve2',
          'KSPSolve', 'MatMult', 'PCApply', 'firedrake.assemble.assemble')
for line in lines:
    if line.startswith(summary) or line.split(' ')[0] in events:
        print(line)

Time (sec):           1.726e+00     1.000   1.726e+00
Flops:                2.978e+07     1.000   2.978e+07  2.978e+07
Event                Count      Time (sec)     Flop                              --- Global ---  --- Stage ----  Total
                   Max Ratio  Max     Ratio   Max  Ratio  Mess   AvgLen  Reduct  %T %F %M %L %R  %T %F %M %L %R Mflop/s
MatMult              200 1.0 3.8247e-03 1.0 1.08e+07 1.0 0.0e+00 0.0e+00 0.0e+00  0 36  0  0  0   1 36  0  0  0  2818
PCApply              202 1.0 4.0051e-04 1.0 8.53e+05 1.0 0.0e+00 0.0e+00 0.0e+00  0  3  0  0  0   0  3  0  0  0  2131
KSPSolve               2 1.0 5.5669e-03 1.0 2.18e+07 1.0 0.0e+00 0.0e+00 0.0e+00  0 73  0  0  0   2 73  0  0  0  3917
MyMesh                 1 1.0 2.1857e-01 1.0 0.00e+00 0.0 0.0e+00 0.0e+00 0.0e+00 13  0  0  0  0  66  0  0  0  0     0
MyAssemble             1 1.0 4.4000e-02 1.0 3.63e+06 1.0 0.0e+00 0.0e+00 0.0e+00  3 12  0  0  0  13 12  0  0  0    83
firedrake.assemble.assemble       4 1.0 5.1286e-02 1.0 7.27e+06 1.0 0.0e+00 0.0e+00 0.0e+00  3 24  0  0  0  15 24  0  0  0   142
MySolve                1 1.0 2.8964e-02 1.0 1.13e+07 1.0 0.0e+00 0.0e+00 0.0e+00  2 38  0  0  0   9 38  0  0  0   389
MyAssemble2            1 1.0 7.3226e-03 1.0 3.63e+06 1.0 0.0e+00 0.0e+00 0.0e+00  0 12  0  0  0   2 12  0  0  0   496
MySolve2               1 1.0 8.2699e-03 1.0 1.13e+07 1.0 0.0e+00 0.0e+00 0.0e+00  0 38  0  0  0   2 38  0  0  0  1361

这就是脚本里加 -log_view 时会看到的表格 (完整输出有一百多行, 这里只留了表头和几个事件). 可以对照前面”读懂 -log_view 的输出”一节逐列看: 自定义事件和 PETSc 内部事件混在同一张表里, KSPSolve 的 Count 是 2, 正好对应两次求解; 单进程运行时凡是非零量的比值都是 1.0 (某一项本身为 0 时 PETSc 直接打成 0.0, 例如 MyMesh 那行 Flop 的比值), Mess、AvgLen、Reduct 三列全为 0. 表里的 firedrake.assemble.assemble 是 Firedrake 自己标注的事件, 它的名字超过 16 个字符, 因此后面的列整体右移了, 正是上一节说的那种情况.

This is the table one sees when -log_view is added to a script (the full output has more than a hundred lines, only the header and a few events are kept here). It can be read column by column against the section “Reading the output of -log_view” above: the custom events and PETSc’s internal events are mixed in the same table, and the Count of KSPSolve is 2, matching the two solves; in a single-process run the ratio of every nonzero quantity is 1.0 (when a quantity is itself 0 PETSc simply prints 0.0, for example the Flop ratio on the MyMesh line), and the three columns Mess, AvgLen, Reduct are all 0. The firedrake.assemble.assemble in the table is an event marked by Firedrake itself; its name exceeds 16 characters, so the columns after it are shifted to the right, exactly the situation described in the previous section.

3.2.1. 写成脚本运行 Running as a script

命令行选项只能用在脚本上. 脚本 py/profile_poisson.py 是同一个算例, 但去掉了 PETSc.Log.begin(), 改由 -log_view 自动开启日志, 并且用装饰器的写法标注组装:

Command-line options can only be used with scripts. The script py/profile_poisson.py is the same example, but with PETSc.Log.begin() removed: the log is turned on automatically by -log_view instead, and the assembly is marked with the decorator form:

"""用 PETSc 自定义事件标注 Poisson 求解的各个阶段, 配合 -log_view 使用.

在 firedrake 目录下运行:

    python3 py/profile_poisson.py -log_view
    python3 py/profile_poisson.py -log_view :profile.txt:ascii_flamegraph

脚本中没有调用 PETSc.Log.begin(): 命令行传了 -log_view 时 PETSc 已经自己把日志
开好了 (普通格式开的是扁平日志, :...:ascii_xml 和 :...:ascii_flamegraph 开的是
嵌套日志). 这时再调用一次 Log.begin() 会额外启动一个扁平日志处理器; 用后两种
嵌套格式时, 程序退出会报 "Trying to end paused event, not allowed".
"""
from firedrake import *
from firedrake.petsc import PETSc


@PETSc.Log.EventDecorator('MyAssemble')
def build_system(a, L, bc):
    return assemble(a, bcs=bc), assemble(L, bcs=bc)


N = 64
with PETSc.Log.Event('MyMesh'):
    mesh = UnitSquareMesh(N, N)
    V = FunctionSpace(mesh, 'CG', 1)

x, y = SpatialCoordinate(mesh)
u, v = TrialFunction(V), TestFunction(V)
a = inner(grad(u), grad(v))*dx
L = inner(sin(pi*x)*sin(pi*y), v)*dx
bc = DirichletBC(V, 0, 'on_boundary')
u_h = Function(V, name='u_h')

A, b = build_system(a, L, bc)

with PETSc.Log.Event('MySolve'):
    solve(A, u_h, b, solver_parameters={'ksp_type': 'cg',
                                        'pc_type': 'jacobi',
                                        'ksp_rtol': 1e-10})

PETSc.Sys.Print(f'dofs = {V.dim()}, L2 norm of u_h = {norm(u_h):.6e}')

在激活了 Firedrake 环境的终端中, 切换到本笔记本所在的 firedrake 目录后运行In a terminal with the Firedrake environment activated, change to the firedrake directory containing this notebook and run

python3 py/profile_poisson.py -log_view

即可看到完整的性能摘要; 换成to see the full performance summary; replacing it with

python3 py/profile_poisson.py -log_view :profile.txt:ascii_flamegraph

则会在当前目录生成火焰图文件 profile.txt. 用generates the flame graph file profile.txt in the current directory. Running

mpiexec -n 4 python3 py/profile_poisson.py -log_view

并行运行时, 表格中的最大最小比值和 MPI 相关的列才会真正有内容, 前面说的负载均衡判断也才用得上.

找到瓶颈之后如何改, 可以参考 Firedrake 文档 Optimising 的 Common performance issues 一节, 其中最常见的一条是: 每次调用 solve() 都会新建一个 PETSc 求解器对象, 在循环里反复求解时应当把 NonlinearVariationalProblem 与 NonlinearVariationalSolver 建在循环外面复用.

in parallel is what makes the max/min ratios and the MPI-related columns of the table carry real content, and only then does the load balance assessment described above become usable.

For what to do once a bottleneck has been found, see the Common performance issues section of Optimising in the Firedrake documentation. The most common item there is that every call to solve() creates a new PETSc solver object, so when solving repeatedly in a loop the NonlinearVariationalProblem and the NonlinearVariationalSolver should be created outside the loop and reused.