一探究竟:善用 MaxCompute Studio 分析 SQL 作业

头疼的问题

MaxCompute 用户一个常见的问题是:同一个周期任务,为什么最近几天比之前慢了很多?或者为什么之前都能按时产出的作业最近经常破线?

通常来说,引起作业执行变慢的原因有:quota 组资源不足、输入数据量变动、数据分布情况变动、平台硬件故障引发重跑等。本文主要针对数据变动引起的作业慢问题,介绍用户如何通过 MaxCompute Studio 的作业执行图及作业详情功能来自助定位问题。

MaxCompute Studio 登场

我们举个例子来说。 下面是同一个任务分别在5月7日,5月9日的执行情况,下面分别称为作业一、作业二:

image.png | left | 614x613

 


作业一,执行时长 24分38秒

image.png | left | 614x613

 


作业二,执行时长 9分40秒

先来,对比下 SQL 和执行计划

通常来说,进行两次执行对比前,要先对比一下两次执行的 SQL 脚本是否相同,如果在这之间用户改动过作业脚本,就需要先分析改动的部分造成的影响。如果脚本内容一致,随后还需要比较执行计划是否一致,可以通过  MaxCompute  Studio  的作业执行计划图功能来分析(参看文档),可视化地看看两次执行的计划图长得一样不一样。 (作业对比的功能正在开发中,下个版本的 Studio 中就可以一键对比两个作业,标注出 SQL 脚本及其它部分的不同之处啦,敬请期待)

在上面这个例子中两个作业的 SQL 脚本及执行计划完全一致,出于数据安全考虑,此处不粘贴具体 SQL 的内容。

再来,对比数据量

第二步要看一下作业输入数据量有没有明显变化,有可能是某一天输入表或分区的数据量暴涨导致了作业执行变慢。作业输入数据在 Detail 页面左侧,那里列出了这个作业所有输入的数据表和最终输出的数据表。 展开 输入->Table Name 可以查看详细信息,包括是哪个 Fuxi 任务读取了这个表,读取了多少条记录以及读取的数据量大小。这些信息,也标注在作业执行计划图 graph 上,方便查看。如下图所示,

image.png | left | 747x330

 


作业一的输入表及读取数据

image.png | left | 741x330

 


作业二的输入表及读取数据

也可以从graph上直接读取输入行数或者字节数(默认展示行数,可在边上右键切换为字节数):

image.png | left | 620x491

 


作业一 graph输入行数

image.png | left | 620x496

 


作业二 graph输入行数

在这个例子中,从输入数据量来看,两次执行的输入数据量差别不大。

作业回放是把利器

第三步,那到底作业运行情况是怎样的呢?运行那么长时间,或花费在哪儿了呢?不急,快快使用作业回放!
在 Studio 中作业执行计划图底部提供的作业回放工具条,允许用户在 30 秒内快速回放作业执行进度的全过程!这样我们就可以迅速地了解到底是哪个 Task 耗时最多,或者处理得数据最多,或者输出的数据最多等等。

通过回放重现作业执行过程,Studio 提供进度图以及热度图方便从不同维度进行作业分析。

job_graph1.gif | center

 


作业一 进度图回放

job_graph2.gif | center

 


作业二 进度图回放

从回放中可以看出
(1)J6_2_4_5 task是整个作业瓶颈,时间消耗最多,从task热度图中也能发现该节点明显热于其它节点。(时间热度图上越红代表运行时间越长,数据热度图上越红代表处理数据越多)

image.png | left | 827x449

(2)同时对比两个作业的回放过程,能够比较明显地发现作业一在J6_2_4_5运行时长要大于作业二,说明作业一在J6_2_4_5阶段变慢了,初步怀疑有长尾节点产生。

接下来切换到时序图tab,比较两个作业的执行timeline:

image.png | left | 747x337

 


作业一 执行timeline

image.png | left | 747x314

 


作业二 执行timeline

虽然两个作业timeline的时间尺度不同,但是可以明显看出,作业一中J6_2_4_5 占了更长的比例,由此可以断定是J6_2_4_5 在05-07执行(也就是作业一)发生可能长尾,导致整个作业执行变慢。

进入深水区

第四步,通过graph或detail tab 对比J6_2_4_5 的输入数据量

image.png | left | 620x194

 


作业一 detail tab

image.png | left | 620x197

 


作业二 detail tab

关注上图中J6_2_4_5 输入数据量和统计信息,通过比较可看出,两次执行的J6_2_4_5 输入数据量基本相同,1.58万亿字节 vs 1.7万亿字节,从统计信息来看,累计执行时间及平均时间也基本相同:292398 vs 307628, 72s vs 76s 但作业一 fuxi instances中的最长执行时间为710s, 由此可以认定是某几个fuxi instance长尾导致了J6_2_4_5 这个fuxi task的长尾。

第五步,对两个 J6_2_4_5 fuxi instance 列表按照latency 排序:

image.png | left | 620x108

 


作业一

image.png | left | 620x108

 


作业二

或者转到分析tab下的长尾页面查找长尾节点:注意这个图中的比例尺是以等比而不是等差方式标定的,因此,上面突出的比较长的毛刺就很可能是长尾的实例了。可以通过浮动窗口中的具体信息来判断。 另外 Studio 也提供了诊断的页面,来自动找出超过平均实例执行时间两倍的长尾实例。

image.png | left | 693x294

 


作业一

image.png | left | 620x286

 


作业二

从上面fuxi instance 输入数据对比可以确定,因为J6_2_4_5#1912_0 这个instance 数据倾斜导致整个作业一长尾。即J6_2_4_5#1912_0 是latency排第二的输入数据量的7倍!

渐入佳境,刨根问底

第六步,查看单个instance的执行日志,并通过job graph分析J6_2_4_5的具体执行计划,找到导致长尾的数据来源。

image.png | left | 607x304

image.png | left | 620x510

image.png | left | 620x310

打开J6_2_4_5的operator graph, 可以看到有两个join:Merge Join2和Merge Join3,这里以Merge Join2为例展示如何查找数据来源。

从Merge Join2中可看到join key:_col13, user_id。 其中_col13 来自于J5, 点开J5后发现_col13来自IF(ISNULL(HOT_SELLER_MAP(sellerid)),sellerid,CONCAT(seller,TOSTRING(RAND()))) 说明_col13由seller决定,该seller来自于M4和M3。

image.png | left | 827x558

 


J5 operator详细信息

 

分别打开M4和M3的Operator详细信息,可以看到seller 分别来自tmp_s_dw_log_app_user_track_pre_1_20180508 和dim_feed_shop。

image.png | left | 827x611

 


M4 Operator详细信息

 

image.png | left | 662x601

 


M3 Operator详细信息

同理可以分析出Merge Join2 的user_id 来自于dim_tb_shop。

最后,通过写sql模拟产生对应的userid及_col13,比较这两个字段的数据量大小,在针对sql脚本进行优化即可。sql脚本优化不在本文介绍范围,因此不在此赘述。

回顾一下

有了 MaxCompute Studio 作业分析这样趁手的工具,遇到各种 MaxCompute 作业的问题就不再束手无策了,甚至,咱们都没有打开那 “让人悲喜交加”的 Logview 不是?

本文作者:皓平

posted @ 2018-05-25 11:02  zhaowei121  阅读(306)  评论(0编辑  收藏  举报