GBase 8a MPP 在性能分析中，单机性能分析是比较重要的一部分，通常，可以通过单机trace进行一些性能分析工作：
1）通过获取SQL在不同node上每步的详细执行时间，可以通过对比找出差异，比如计算的数据量，聚集算法的选择，buffer的大小等等。
2）了解SQL执行过程中各阶段的耗时，从而对耗时较长的部分进行重点优化。
3）对内存使用，IO使用有一个相对量化的数据。
通过以下命令设置单机日志级别：
设置全局参数，需重新登录session生效：set global gbase_sql_trace=on;set global gbase_sql_trace_level=3;
设置session参数，仅在当前session生效：set gbase_sql_trace=on;set gbase_sql_trace_level=3;
当执行SQL后，node会生成所有SQL执行的详细过程。日志位置一般在node安装目录下，比如：/opt/gnode/log/gbase_root_xxx_xxx.trc
以下是一个query的例子，通常日志内容比较多，我们可以先过滤一些关键字来查看：
grep -i ‘END\|Done’ xxx.trc
以下是一段过滤后的日志：
2022-04-13
15:00:21.751 [M: 35G, 48B,D:
0B] [DC: 0, 0] END Serial Aggregation. (time used:
0.000s)
2022-04-13
15:00:21.756 [M: 35G, 0B,D:
0B] [DC: 0, 0] END Smart Scan. (time used: 0.000s)
2022-04-13
15:00:22.173 [M: 35G, 0B,D:
0B] [DC: 763, 0] END Scan. (time used: 0.417s)
2022-04-13
15:00:22.173 [M: 35G, 0B,D:
0B] [DC: 763, 0] END Join(time used: 0.000s)
2022-04-13
15:00:22.173 [M: 35G, 0B,D:
0B] [DC: 763, 0] END Scan(after join)(time used: 0.000s)
2022-04-13
15:00:22.173 [M: 35G, 48B,D:
0B] [DC: 763, 0] END Serial Aggregation. (time used:
0.000s)
2022-04-13
15:00:22.202 [M: 35G, 48B,D:
0B] [DC: 0, 0] END Serial Aggregation. (time used:
0.001s)
2022-04-13
15:00:22.205 [M: 35G, 48B,D:
0B] [DC: 0, 0] END Serial Aggregation. (time used:
0.000s)
2022-04-13
15:00:22.208 [M: 35G, 48B,D:
0B] [DC: 0, 0] END Serial Aggregation. (time used:
0.001s)
2022-04-13
15:00:22.211 [M: 35G, 48B,D:
0B] [DC: 0, 0] END Serial Aggregation. (time used:
0.000s)
2022-04-13
15:00:22.283 [M: 35G, 0B,D:
0B] [DC: 0, 0] END Smart Scan. (time used: 0.000s)
2022-04-13
15:00:22.284 [M: 35G, 0B,D:
0B] [DC: 0, 0] END Scan. (time used: 0.000s)
2022-04-13
15:00:22.284 [M: 35G, 0B,D:
0B] [DC: 0, 0] END Join(time used: 0.000s)
2022-04-13
15:00:22.284 [M: 35G, 0B,D:
0B] [DC: 0, 0] END Scan(after join)(time used: 0.000s)
2022-04-13
15:00:22.304 [M: 35G, 0B,D:
0B] [DC: 0, 0] END Smart Scan. (time used: 0.000s)
2022-04-13
15:00:22.721 [M: 35G, 0B,D:
0B] [DC: 763, 0] END Scan. (time used: 0.416s)
2022-04-13
15:00:22.721 [M: 35G, 0B,D:
0B] [DC: 763, 0] END Join(time used: 0.000s)
2022-04-13
15:00:22.721 [M: 35G, 0B,D:
0B] [DC: 763, 0] END Scan(after join)(time used: 0.000s)
2022-04-13
15:00:22.960 [M: 35G, 0B,D:
0B] [DC: 0,
0] END Smart Scan. (time used: 0.000s)
2022-04-13
15:00:22.961 [M: 35G, 0B,D:
0B] [DC: 0, 0] END Scan. (time used: 0.000s)
2022-04-13
15:00:22.961 [M: 35G, 0B,D:
0B] [DC: 0, 0] END Join(time used: 0.000s)
2022-04-13 15:00:22.961
[M: 35G, 0B,D:
0B] [DC: 0, 0] END Scan(after join)(time used: 0.000s)
2022-04-13
15:00:22.975 [M: 35G, 0B,D:
0B] [DC: 0, 0] END Smart Scan. (time used: 0.000s)
2022-04-13
15:00:22.975 [M: 35G, 0B,D:
0B] [DC: 0, 0]
END Scan. (time used: 0.000s)
2022-04-13
15:00:38.225 [M: 35G,1.74G,D: 0B] [DC: 22928, 166] END hybrid hash join: partition(-1/1):
(time used: 14.988s)
2022-04-13
15:00:38.424 [M: 35G, 0B,D:
0B] [DC: 22928, 166] cnd(0)
Done(time used: 15.444s)
2022-04-13
15:00:48.347 [M: 35G,7.22G,D: 0B] [DC: 51579, 166] END hybrid hash join: partition(-1/1):
(time used: 8.897s)
2022-04-13
15:00:51.458 [M: 35G, 327M,D: 622M] [DC:
51579, 166] cnd(1) Done(time used:
13.034s)
2022-04-13
15:00:51.458 [M: 35G, 327M,D: 622M] [DC:
51579, 166] END Join(time used:
28.479s)
2022-04-13
15:00:51.458 [M: 35G, 327M,D: 622M] [DC:
51579, 166] END Scan(after join)(time
used: 0.000s)
2022-04-13
15:01:08.806 [M: 35G, 0B,D:
0B] [DC: 0, 0] END Smart Scan. (time used: 0.000s)
2022-04-13
15:01:08.806 [M: 35G, 0B,D:
0B] [DC: 0, 0] END Scan. (time used: 0.000s)
2022-04-13
15:01:08.806 [M: 35G, 0B,D:
0B] [DC: 0, 0] END Join(time used: 0.000s)
2022-04-13
15:01:08.806 [M: 35G, 0B,D:
0B] [DC: 0, 0] END Scan(after join)(time used: 0.000s)
2022-04-13
15:01:08.823 [M: 35G, 0B,D:
0B] [DC: 0,
0] END Smart Scan. (time used: 0.000s)
2022-04-13
15:01:08.823 [M: 35G, 0B,D:
0B] [DC: 0, 0] END Scan. (time used: 0.000s)
2022-04-13
15:01:08.905 [M: 35G, 829M,D: 0B] [DC:
40, 0] END hybrid hash join:
partition(-1/1): (time used: 0.073s)
2022-04-13
15:01:08.972 [M: 35G, 14M,D:
14M] [DC: 40, 0] cnd(1) Done(time used: 0.149s)
2022-04-13
15:01:11.706 [M: 36G,2.47G,D: 14M] [DC:
118, 1244] END hybrid hash join:
partition(-1/1): (time used: 2.353s)
2022-04-13
15:01:13.337 [M: 36G, 171M,D: 466M]
[DC: 118, 1244] cnd(0) Done(time used: 4.365s)
2022-04-13
15:01:13.337 [M: 36G, 171M,D: 466M]
[DC: 118, 1244] END Join(time used: 4.514s)
2022-04-13
15:01:13.337 [M: 36G, 171M,D: 466M]
[DC: 118, 1244] END Scan(after join)(time used: 0.000s)
2022-04-13
15:01:21.679 [M: 37G, 0B,D:
0B] [DC: 0, 0] | END Smart Scan. (time used: 0.000s)
2022-04-13
15:01:21.679 [M: 37G, 0B,D:
0B] [DC: 0, 0] | END Scan. (time used: 0.000s)
2022-04-13
15:01:21.679 [M: 37G, 0B,D:
0B] [DC: 0, 0] | END Join(time used: 0.000s)
2022-04-13
15:01:21.679 [M: 37G, 0B,D:
0B] [DC: 0, 0] | END Scan(after join)(time used:
0.000s)
2022-04-13
15:01:21.679 [M: 37G, 80B,D:
0B] [DC: 0, 0] END Serial Aggregation. (time used:
0.000s)
2022-04-13
15:01:21.688 [M: 37G, 0B,D:
0B] [DC: 0, 0] | END Smart Scan. (time used: 0.000s)
2022-04-13
15:01:21.689 [M: 37G, 0B,D:
0B] [DC: 0, 0] | END Scan. (time used: 0.000s)
2022-04-13
15:01:31.610 [M: 38G,7.54G,D: 0B] [DC:
6180, 2488] | END hybrid hash
join: partition(-1/1): (time used: 9.526s)
2022-04-13
15:01:34.048 [M: 38G, 326M,D: 621M]
[DC: 6180, 2488] | cnd(1, 0) Done(time used: 12.359s)
2022-04-13
15:01:34.048 [M: 38G, 326M,D: 621M]
[DC: 6180, 2488] | END Join(time used: 12.359s)
2022-04-13
15:01:34.048 [M: 38G, 326M,D: 621M]
[DC: 6180, 2488] | END Scan(after join)(time used:
0.000s)
2022-04-13
15:01:52.929 [M: 46G,1.57G,D: 621M]
[DC:1821233, 8708] | Parallel
Materialization Done. (time used: 18.881s)
2022-04-13
15:01:53.144 [M: 46G, 326M,D: 621M]
[DC:1821629, 8708] End parallel
splitting for aggregation (split_type = 2)(time used: 0.001s)
2022-04-13
15:01:55.876 [M: 46G, 326M,D: 621M]
[DC:1825382, 8708] END Parallel
Aggregation. (time used: 2.945s)
2022-04-13
15:01:56.916 [M: 41G, 0B,D:
0B] [DC: 0, 0] END Smart Scan. (time used: 0.000s)
2022-04-13
15:01:56.916 [M: 41G, 0B,D:
0B] [DC: 0, 0] END Scan. (time used: 0.000s)
2022-04-13
15:01:56.916 [M: 41G, 0B,D:
0B] [DC: 0, 0] END Join(time used: 0.000s)
2022-04-13
15:01:56.916 [M: 41G, 0B,D:
0B] [DC: 0, 0] END Scan(after join)(time used: 0.000s)
2022-04-13
15:01:56.916 [M: 41G, 80B,D:
0B] [DC: 0, 0] END Serial Aggregation. (time used:
0.000s)
2022-04-13
15:01:56.922 [M: 41G, 128B,D: 0B] [DC:
6, 3] END Serial Aggregation.
(time used: 0.004s)
2022-04-13
15:01:56.930 [M: 41G, 17K,D:
0B] [DC: 3, 3] END Sort. (time used: 0.001s)
通过以上信息可以获取到一些关键步骤的耗时：
1）cnd0 hash join 15s
2）cnd1 hash join 13s
3）hash join 4.5s
4）hash join 12.3s
5）Materialization 18.8s
6）Parallel Aggregation 3s
其中在parallel Materialization内存占用 46G，DC读取缓存命中1821233个，磁盘读取8708个，是系统负载最重的阶段。
2022-04-13
15:01:52.929 [M: 46G,1.57G,D: 621M]
[DC:1821233, 8708] | Parallel
Materialization Done. (time used: 18.881s)
可以对该trace文件阅读，查看在parallelMaterialization阶段是否存在性能问题：
2022-04-13
15:01:34.048 [M: 38G, 326M,D: 621M]
[DC: 6180, 2488] | BEGIN Materialization(81498863 rows,
page size: 16777216)
2022-04-13
15:01:34.430 [M: 38G,1.25G,D: 621M]
[DC: 6180, 2488] | Parallel materialization prepared
2022-04-13
15:01:36.144 [M: 42G,1.25G,D: 621M]
[DC:109751, 8708] | ( 0)Materialization
0 to 393215 already
2022-04-13
15:01:36.144 [M: 42G,1.25G,D: 621M]
[DC:109751, 8708] | ( 0)Materialization
0 to 393215 already
……
2022-04-13
15:01:36.405 [M: 42G,1.57G,D: 621M]
[DC:110639, 8708] | Parallel
materialization 0 to 15728639 already
2022-04-13
15:01:36.405 [M: 42G,1.57G,D: 621M]
[DC:110639, 8708] | 1/6 round(s)
materialization done
单机会根据需要Materialization的行数，以及buffer 大小，来计算每轮可以物化的行数，在该环境上，81498863行数据换算成DC大概是1244个（每65536行一个DC），parallel参数是40，根据trace显示，每线程可以物化的行数是393216行，换成DC是6个DC，40并行，每次可以处理240DC。那么理论上，1244个DC大概需要6轮就能完成，最后一轮只需要处理44个DC。从日志看1/6 round耗时大概是2s（从prepared到第一轮结束），预计materizlization大概是10-12s左右，跟实际18.8s有较大出入，所有需要再次查看后面的materialization日志，到底在干什么。
2022-04-13
15:01:36.546 [M: 42G,1.57G,D: 621M]
[DC:126181, 8708] | Parallel
materialization 15728640 to 15794175 already
2022-04-13
15:01:36.546 [M: 42G,1.57G,D: 621M]
[DC:126181, 8708] | 2/6 round(s)
materialization done
