HiveのUDFを開発する際のデバッグログの出力方法
hiveのUDFを開発・デバッグしている時に、
UDFの挙動をログに出力して確認したいことがあるので。
hiveのUDFで、ログを出力し確認する方法をまとめておきます。
UDFの作り方は、以下のエントリを参考にしてください。
HiveのUDFを作る手順のメモ | takemikami.com
http://takemikami.com/2016/09/06/HiveUDF.html
この手順は、macos上の「Hive 2.1.0」で確認しています。
ログ出力を埋め込む
UDFのコードにログ出力を埋め込みます。
「Apache Commons Logging」でログを出力するコードを追加します。
以下のコード例では、
evaluateメソッドの初めにデバッグログを出力するようにしています。
src/main/java/com/takemikami/hiveudfsample/Lower.java
package com.takemikami.hiveudfsample;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.apache.hadoop.hive.ql.exec.UDF;
import org.apache.hadoop.io.Text;
public final class Lower extends UDF {
private static Log logger = LogFactory.getLog(Lower.class);
public Text evaluate(final Text s) {
logger.debug("enter Lower.evaluate, s=" + s.toString());
if (s == null) { return null; }
return new Text(s.toString().toLowerCase());
}
}
コンソールにログを出力する
hiveのログ出力の設定は「hive-log4j2.properties」に記載されています。
github上で確認したい場合はこちら、
https://github.com/apache/hive/blob/master/common/src/main/resources/hive-log4j2.properties
macosでhomebrewを使ってinstallした場合は、以下のファイルになります。
/usr/local/Cellar/hive/※hiveのバージョン※/libexec/conf/hive-log4j2.properties.template
この設定ファイルを見ると「hive.root.logger」でロガーを指定できることがわかります。
そこで、以下のようにパラメータを指定してhiveコマンドを起動します。
$ hive -hiveconf hive.root.logger=DEBUG,console
先ほどログを埋め込んだUDFを、以下のように呼び出します。
hive> add jar ※UDF開発ディレクトリのパス※/build/libs/hiveudf-sample.jar;
hive> create temporary function lower as 'com.takemikami.hiveudfsample.Lower';
hive> select lower('AAA');
コンソールに以下のようなログが出力されます。
17/08/09 11:29:08 [main]: DEBUG hiveudfsample.Lower: enter Lower.evaluate, s=AAA
上記以外にも大量のログが出力され、ログを追うのが難しいと思われるので、
次の項では、grepしやすいようにファイルにログを出力する方法を示します。
ファイルにログを出力する
次に、ファイルにログを出力してみます。
前項と同じように、ログ出力の設定を行ってhiveコマンドを起動します。
$ hive -hiveconf hive.root.logger=DEBUG,DRFA -hiveconf hive.log.dir=※ログの出力先パス※ -hiveconf hive.log.file=hive-debug.log
前項と同じようにUDFを呼び出します。
hive> add jar ※UDF開発ディレクトリのパス※/build/libs/hiveudf-sample.jar;
hive> create temporary function lower as 'com.takemikami.hiveudfsample.Lower';
hive> select lower('AAA');
実行後、以下のコマンドでログファイルを確認します。
$ cat ※ログの出力先パス※/hive-debug.log | grep hiveudfsample.Lower
以下のようなデバッグログが出力出来ていることを確認できます。
2017-08-09T11:48:59,337 DEBUG [main]: exec.FunctionRegistry (:()) - Method did match: passed = [string] accepted = [string] method = public org.apache.hadoop.io.Text com.takemikami.hiveudfsample.Lower.evaluate(org.apache.hadoop.io.Text)
2017-08-09T11:48:59,337 DEBUG [main]: hiveudfsample.Lower (:()) - enter Lower.evaluate, s=AAA
2017-08-09T11:48:59,396 DEBUG [main]: exec.FunctionRegistry (:()) - Method did match: passed = [string] accepted = [string] method = public org.apache.hadoop.io.Text com.takemikami.hiveudfsample.Lower.evaluate(org.apache.hadoop.io.Text)
2017-08-09T11:48:59,396 DEBUG [main]: hiveudfsample.Lower (:()) - enter Lower.evaluate, s=AAA
UDFを作るときはあまり必要ないかも知れないですが。
UDAF,UDTFを作るときは、
このようにログを出力して挙動を追いながら開発出来ると、
効率良くデバッグ出来るのでは無いかな、と思います。