天天看点

基于自定义日志打印的UDAF调试

看到最近有一些用户,代码在本地ide环境里调试成功了后,到线上调试出现结果不符合预期的情况。因为ide里无法模拟多个worker进行分布式调试udaf的场景,所以有一些bug可能需要到线上用一些简单的测试数据进行调试。这里用最简单的手工打印日志的方法,针对代码调试中最麻烦的udaf的例子做一次调试。通过问题的定位和解决,希望能给大家在面对udf的线上调试的时候提供一些思路。

首先,线上的真实数据可能非常多,千万不要直接对着上亿条数据直接调试,否则很难定位到原因。面对线上的问题,最好先根据数据情况,简化计算场景。比如我这里,就先把测试数据简化成:

可以看到模拟数据是

基于自定义日志打印的UDAF调试

这样一共6一条记录,分布在2个不同的分区里。

我们希望udaf的计算结果能类似:

基于自定义日志打印的UDAF调试

在本地已经调试好的java代码如下:

因为逻辑不复杂,所以也没有添加更多的注释。可以看到用一个map来存放中间数据,并用tostring来做序列化,然后写了段简单的代码进行反序列化。到了terminate后,拼成需要的结果再返回。

打包后,注册一下函数并测试一下结果:

可以看到,这里c的值不知道为什么变成了4,这个是在本地没有发现的问题。还好我们的数据量比较小,所以定位起来比较方便。目前的思路是,我们已经明确输入的数据是什么,也知道我们期望的结果是什么。那么我们首先需要知道,在中间数据的一步步流转的过程中,从哪里开始和我们预期的不一样。定位到是哪里开始数据和预期不符合后,再结合上下文的代码逻辑,定位到问题的原因。

首先我们给代码加上一些异常打印,看看流转过程中的数据分别是什么。通过system.err.println,我们把我们想要的信息打印到stderr里。

先打印了这么几个方法里。这样打印的思路主要是,看看每次调用的时候的数据输入输出是什么。从而定位到是从哪里开始出现的问题。

打包,替换掉jar包,然后重新调用一下函数,可以看到

结果数据是不变的,但是我们可以看下日志。打开里面的logview,可以看到:

基于自定义日志打印的UDAF调试

里面的日志,2个map里的日志分别是:

看到都是对的,然后看下reduce里的结果:

看一下,partial in merge:{a=2, b=1, c=2} 这条数据不符合预期。照道理说,我们前面输出的是output in iterate:{a=2, b=1},怎么到这里就变成了{a=2, b=1, c=2}了呢。

这种的变化,是在多个worker之间进行传递的时候,我们做了序列号和反序列化,于是我们在这里又打了一些日志:

重新打包跑一次,这次看到的日志是这样:

果然反序列化的时候输出的结果就有问题了。但是从这里还没有明确的证据说明是哪行代码出的问题。看到dict输出的结果不符合预期,我们先看看输入的时候是什么。于是再加一行日志:

看到这会的reduce阶段日志

这下真相大白了。我们第二次调用readfields序列化{a=2, b=1}这个字符串的时候,发现本来应该为空的dict的内容竟然是上次计算后的结果。实际上,在readfields里,相同worker里的sumbuffer被复用了。这种情况下,为了保证计算的准确性,我们可以自己清空一下dict的内容

这下终于对了

代码还有其他更多可以优化的地方。不过这次为了能简单说明调试的过程,简化代码逻辑,就没在这方面再多下功夫。实际的业务代码里还需要考虑到性能和异常捕捉等问题。

system.err.println这个办法虽然很笨,但是很有效,不是吗?