天天看點

基于自定義日志列印的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這個辦法雖然很笨,但是很有效,不是嗎?