HBase와 호스트이름

Naver Pinpoint GitHub에 한 중국 유저가 Windows 7 환경에서 데이터 수집이 안된다는 이슈를 등록하였다. Pinpoint를 Windows에서 실행할 수 있도록 추가한 사람으로써 해당 문제를 확인하고 싶었다.

그래서 최신 Pinpoint가 1.0.4 RC를 받아 Windows 8.1에서 실행했는데 이슈로 등록된 문제가 나에게도 재현되었다.

HBase와 Pinpoint를 분산모드에서 테스트하기 위해 Linux에 설치하기 전까지 Windows에서 정상적으로 사용했었는데? 왜??

일단 HBase 로그를 살펴보았는데 의심스러운 부분이 눈에 들어왔다.

INFO util.VersionInfo: HBase 0.94.26
INFO server.ZooKeeperServer: Server environment:host.name=BK-P2.FOO.COM
...
INFO regionserver.HRegionServer: Connected to master at BK-P2.FOO.COM/192.168.56.1:56332
INFO regionserver.HRegionServer: Telling master at BK-P2.FOO.COM,56332,1423732578852 that we are up with port=56360, startcode=1423732588081

Master 호스트는 내가 사용하던 것인데 Region Server에 대해 낯선 IP 주소로 있었다. IP 주소를 확인해보니 최근 설치한 Oracle VirtualBox 용 네트워크 어댑터에 할당된 것이다.

C:> ipconfig /all
Windows IP Configuration
   Host Name           : BK-P2
   Primary Dns suffix  : foo.com
...

Ethernet adapter Local Area Connection:
   Description          : Realtek PCIe GBE Family Controller
   IPv4 Address         : 192.168.123.306

Ethernet adapter VirtualBox Host-Only Network:
   Description          : VirtualBox Host-Only Ethernet Adapter
   IPv4 Address         : 192.168.56.1

그리고 Pinpoint Collector와 TestApp을 실행했을 때 quickstart.collector.log 파일에 다음과 같은 로그가 발생했다.

[INFO ](o.a.z.ClientCnxn                   :1207) Session establishment complete on server 127.0.0.1/127.0.0.1:2181, sessionid = 0x14b7d1318ed0003, negotiated timeout = 40000
[DEBUG](c.n.p.r.s.PinpointServerSocket     :202) messageReceived:RequestPacket{requestId=2, payloadLength=84} channel:[id: 0xb2ae16b0, /127.0.0.1:56526 => /127.0.0.1:29994]
[INFO ](c.n.p.c.h.ApiMetaDataHandler       :51) Received ApiMetaData=TApiMetaData(agentId:test-agent, agentStartTime:1423733151414, apiId:-1, apiInfo:sun.net.www.protocol.http.HttpURLConnection.connect(), line:846)
[DEBUG](c.n.p.c.d.h.HbaseApiMetaDataDao    :53) insert:TApiMetaData(agentId:test-agent, agentStartTime:1423733151414, apiId:-1, apiInfo:sun.net.www.protocol.http.HttpURLConnection.connect(), line:846)
[INFO ](o.a.h.i.HBaseRPC                   :261) Server at BK-P2.FOO.COM/192.168.123.306:56360 could not be reached after 1 tries, giving up.

HBaseRPC가 접속하지 못하는 56360에 대해 확인하기 위해 아래 명령어를 실행했다.

C:\> netstat -an | findstr 56360
  TCP    192.168.56.1:56360     0.0.0.0:0              LISTENING

HBase에서 사용하는 IP 주소와 Pinpoint에서 사용하려는 IP 주소가 달라서 발생한 문제라고 판단했다(나중에 다시 확인하니 이것은 나의 틀린 판단이었다.) 일단 문제 해결을 위해 VirtualBox Host-Only Network 어댑터를 사용 중지 시키고 HBase를 다시 실행해보니 Pinpoint가 정상적으로 동작하는 것을 확인했다.

중국 유저에게 이런 문제가 아닌가 싶어서 이슈에 댓글을 달았는데, 그 유저의 문제는 이것이 아니고 기본적인 HBase 버전 차이 때문에 발생한 것이었다. Pinpoint는 HBase 0.94.x 버전만 지원하는데 0.98.x 버전을 실행한 것이다.

나의 경우는 단지 hosts 파일에 192.168.56.1에 대한 호스트명만 등록만 해주면 해결되었다.

192.168.56.1 bk.vm

이렇게 등록한 후 다시 HBase를 실행하면 다음과 같은 로그를 확인할 수 있다.

INFO util.VersionInfo: HBase 0.94.26
INFO server.ZooKeeperServer: Server environment:host.name=bk.vm
...
INFO regionserver.HRegionServer: Connected to master at bk.vm/192.168.56.1:56332
INFO regionserver.HRegionServer: Telling master at bk.vm,56332,1423732578852 that we are up with port=56360, startcode=1423732588081

즉, Master와 Region Server가 모두 bk.vm 이라는 호스트명으로 동작하는 것이다. 호스트명을 등록하기 전에는 BK-P2.FOO.COM 가 호스트명으로 사용되었다.

결론 적으로 이렇게 호스트명이 바뀐 이유는 Windows 8.1의 IPv6와 내가 사용하는 네트워크의 DHCP에서 IPv6를 지원하기 때문이며, HBase 실행시 네트워크 주소에서 IPv4를 우선하도록 설정했기 때문이다.

hbase-env.cmd 파일을 보면 아래와 같이 java.net.preferIPv4Stack=true 로 정의하여 IPv4를 우선하도록 되어 있다.

set HBASE_OPTS="-XX:+UseConcMarkSweepGC" "-Djava.net.preferIPv4Stack=true"

기본 네트워크 어댑터와는 다르게 Oracle VirtualBox 용 어댑터는 IPv4만 설정되어 있기 때문에 HBase에서 확인하는 호스트명이 바뀐 것이다.

간단하게 호스트명을 확인하는 클래스를 만들어 보고 실행해보았다.

public class Hostname {
    public static void main(String[] args) throws UnknownHostException {
        InetAddress localhost = InetAddress.getLocalHost();
        String hostname = localhost.getHostName();
        String canonicalName = localhost.getCanonicalHostName();
        String hostAddress = localhost.getHostAddress();
        System.out.println("hostname=" + hostname + ",canonicalName=" + canonicalName + ",hostAddress=" + hostAddress);
    }
}

hosts 파일에 호스트 bk.vm 을 등록하지 않으면  getCanonicalHostName() 의 실행 결과가 상당히 오래 걸리는 것을 알 수있다. ZooKeeper는 FQDN을 위해 getCanonicalHostName()을 사용한다.

C:> java Hostname
hostname=BK-P2,canonicalName=BK-P2.FOO.COM/192.168.123.36
C:> java -Djava.net.preferIPv4Stack=true Hostname
hostname=BK-P2,canonicalName=bk.vm/192.168.56.1

Hibernate 4.3 Statement Warning 문제

Naver Pinpoint를 테스트하기 위해 프로젝트의 트랜잭션을 확인하던 중 이상한 것을 발견했다.

Hibernate 4.3 Statement Warning
Naver Pinpoint CallStack Sample

코드 상에 없는 SHOW WARNINGS 라는 질의가 실행된 것이다.

디버그 모드로 원인을 찾아 보니 Hibernate 4.2 버전과는 다르게 Hibernate 4.3에서는 Statement 를 닫을 때 SqlExceptionHelper#logAndClearWarnings(Statement) 를 호출하도록 되어 있다
(4.2에서도 해당 메소드는 있지만 임시 테이블을 만드는 작업을 할 때만 호출한다).

해당 메소드를 보면 다음과 같다:

@SuppressWarnings({"ThrowableResultOfMethodCallIgnored"})
public void handleAndClearWarnings(
 Statement statement,
 WarningHandler handler) {
 // See HHH-9174. Statement#getWarnings can be an expensive call for many JDBC libs. Don't do it unless
 // the log level would actually allow a warning to be logged.
 if (LOG.isEnabled(Level.WARN)) {
 try {
 walkWarnings( statement.getWarnings(), handler );
 }
 catch (SQLException sqlException) {
 // workaround for WebLogic
 LOG.debug( "could not log warnings", sqlException );
 }
 }
 try {
 // Sybase fail if we don't do that, sigh...
 statement.clearWarnings();
 }
 catch (SQLException sqle) {
 LOG.debug( "could not clear warnings", sqle );
 }
}

로그 레벨이 WARN이 가능한 경우 walkWarnings(…)이 실행되고 이것은 Statement#getWarnings()를 호출하는데, MySQL의 경우 실질적으로 SQLError#convertShowWarningsToSQLWarnings(…) 이 실행된다. 이 메소드의 내부에는 다음과 같은 코드가 있어서 SHOW WARNINGS 질의를 실행한다.

/*
 * +---------+------+---------------------------------------------+ |
 * Level | Code | Message |
 * +---------+------+---------------------------------------------+ |
 * Warning | 1265 | Data truncated for column 'field1' at row 1 |
 * +---------+------+---------------------------------------------+
 */
warnRs = stmt.executeQuery("SHOW WARNINGS");

개발 및 CI 환경에서는 도움이 될 수 있겠지만 production 환경에서는 모든 Statement 를 닫을 때마다 문제가 있는지 확인하는 SQL이 실행되는 것은 바람직하지 않다.

production 환경에서 이것이 실행되지 않게 하려면 다음과 같이 로그 레벨을 ERROR로 올린다.

<log4j ...>
  <logger name="org.hibernate.engine.jdbc.spi.SqlExceptionHelper">
    <level value="ERROR" />
  </logger>
</log4j>

Naver Pinpoint

최근 일주일을 Naver Pinpoint와 HBase, 그리고 Hadoop을 테스트하고 있다.

Naver Pinpoint는 오픈소스로 공개된지 얼마되지 않기 때문에 상용 APM에 비해서는 아직 지원하는 에이전트 기능이 부족하고 데이터 필터링에 대한 기능이  부족하지만, 발전 가능성이 높다고 생각한다.

HBase를 단일모드(Standalone)로 테스트를 마치고, 어제부터는 다른 서버에 가상 분산 모드(Pseudo Distributed Mode)로 설치한 후, PC에는 Pinpoint Collector와 Web을 띄워 테스트를 진행중이다.

그리고 현재 개발 및 운영 중인 프로젝트에 Pinpoint 1.0.4-SNAPSHOT 버전을 적용하기 위해서는 다음과 같은 프로파일러 추가가 필요했다.

  • MS JDBC Driver for SQL Server
    현재 jTDS Driver는 지원한다.
  • SQLite

기존 소스를 활용하여 적용하니 해당 연동과 관련된 데이터가 수집되는 것을 확인하였다.