Netty HTTP HelloWorldの起動が600msくらいだったんだけどGraalVMのNative Imageを使うと15msくらいになったー

下記の記事を読んで「えー。実際に手を動かして、自分の目で見てみたいー。」ってなったので、書いてある通りにやってみたら10ms前後でほんとに起動した。へー。その途中で色々と知らないことがたくさんあって面白かった。

## やったことを順番に書いていく
## v1 サンプルプロジェクトを作成
## v2 native-image-maven-plugin を追加
## v3 Unsafe 対応
## v4 ロガー対応
## v5 リフレクション対応
## v6 遅延初期化対応
## v7 速度比較
## 満足した

## やったことを順番に書いていく

GraalVMでNative Imageを作るまでに色々やらなきゃいけないので、やったことを順番に書いていく。ソースコードはここに置いといて、順番にタグ付けしておいた。

使ったのは、GraalVM 1.0-RC15。SDKMAN!で指定した。

❯ sdk current java

Using java version 1.0.0-rc-15-grl

## v1 サンプルプロジェクトを作成

記事にもある通り Netty Exampleの中のHTTPのハローワールドを使ってサンプルプロジェクトを作った。v1がタグね。

maven-assembly-plugin でFatJARを作って実行できるようにしてあるので

      <plugin>
        <artifactId>maven-assembly-plugin</artifactId>
        <version>3.1.1</version>
        <configuration>
          <descriptorRefs>
            <descriptorRef>jar-with-dependencies</descriptorRef>
          </descriptorRefs>
          <archive>
            <manifest>
              <mainClass>com.example.demo.helloworld.HttpHelloWorldServer</mainClass>
            </manifest>
          </archive>
        </configuration>
        <executions>
          <execution>
            <id>make-assembly</id>
            <phase>package</phase>
            <goals>
              <goal>single</goal>
            </goals>
          </execution>
        </executions>
      </plugin>

packageすると

❯ ./mvnw clean package

target ディレクトリーに netty-native-demo-1.0-SNAPSHOT-jar-with-dependencies.jar が生成されるから、それを実行。

❯ java -jar target/netty-native-demo-1.0-SNAPSHOT-jar-with-dependencies.jar
Apr 15, 2019 9:59:48 PM io.netty.handler.logging.LoggingHandler channelRegistered
INFO: [id: 0x4b3bc1c7] REGISTERED
Apr 15, 2019 9:59:48 PM io.netty.handler.logging.LoggingHandler bind
INFO: [id: 0x4b3bc1c7] BIND: 0.0.0.0/0.0.0.0:8080
Open your web browser and navigate to http://127.0.0.1:8080/
Apr 15, 2019 9:59:48 PM io.netty.handler.logging.LoggingHandler channelActive
INFO: [id: 0x4b3bc1c7, L:/0:0:0:0:0:0:0:0:8080] ACTIVE

普通に起動して、Hello Worldが見える。

f:id:bufferings:20190415220143p:plain:w300

じゃ、ここからGraalVMでNative Imageを生成できるようにしていく。

## v2 `native-image-maven-plugin` を追加

記事にあるみたいに直接 native-image コマンドを叩いてもいいんだけど、Mavenでビルドできるのも楽そうでいいなと思って導入してみた。先に言っておくと、この時点ではビルドはエラーになる。

      <plugin>
        <groupId>com.oracle.substratevm</groupId>
        <artifactId>native-image-maven-plugin</artifactId>
        <version>1.0.0-rc15</version>
        <configuration>
          <imageName>netty-example-http</imageName>
        </configuration>
        <executions>
          <execution>
            <goals>
              <goal>native-image</goal>
            </goals>
            <phase>package</phase>
          </execution>
        </executions>
      </plugin>

このプラグインに関しては既に、かずひらさんが書いてくれてた！

いつも僕のためにありがとうございます！ / “Native Image Maven Pluginを使って、GraalVMでネイティブイメージを作る - CLOVER🍀” https://t.co/mEQMuzePrI
— Mitsuyuki Shiiba (@bufferings) 2019年4月14日

❯ ./mvnw clean package

を実行すると、さっきのFatJARが生成された後に、Native Imageのビルドが始まる。で、2種類の警告が出る。

１つ目は sun.misc.Unsafe によるUnsafeなメモリアクセス。 Unsafe を使ってたとしても一般的なパターンで使ってたら native-image がいい感じで対応してくれるんだけど、対応しきれないやつが今回の場合は3つある（最初に書いた参照記事によると、94個はいい感じに対応できてて、3個だけ対応しきれないってことみたい）。

↓適当に改行を入れといた。メッセージが丁寧だね。

Warning: RecomputeFieldValue.ArrayIndexScale automatic substitution failed.
The automatic substitution registration was attempted because a call to sun.misc.Unsafe.arrayIndexScale(Class) was detected
in the static initializer of io.netty.util.internal.PlatformDependent0.
Detailed failure reason(s): The field java.lang.Long.value, where the value produced by the array index scale computation is stored, is not static.                                                                                                                                                                                  

Warning: RecomputeFieldValue.FieldOffset automatic substitution failed.
The automatic substitution registration was attempted because a call to sun.misc.Unsafe.objectFieldOffset(Field) was detected
in the static initializer of io.netty.util.internal.PlatformDependent0.
Add a RecomputeFieldValue.FieldOffset manual substitution for io.netty.util.internal.PlatformDependent0.ADDRESS_FIELD_OFFSET.
Detailed failure reason(s): The argument of Unsafe.objectFieldOffset(Field) is not a constant field.                                                                                                     

Warning: RecomputeFieldValue.ArrayIndexScale automatic substitution failed.
The automatic substitution registration was attempted because a call to sun.misc.Unsafe.arrayIndexScale(Class) was detected
in the static initializer of io.netty.util.internal.shaded.org.jctools.util.UnsafeRefArrayAccess.
Detailed failure reason(s): Could not determine the field where the value produced by the call to sun.misc.Unsafe.arrayIndexScale(Class) for the array index scale computation is stored.
The call is not directly followed by a field store or by a sign extend node followed directly by a field store.

それともう１つはLogger周り。ロガーはよく「実行時にあるやつを使う」みたいな実装がしてあって、Nettyだと InternalLoggerFactory がそういう実装になってる。けど、Substrate VM（Native Imageで使われるVM実装）で動かすときはビルド時にクラスが存在しないといけない。だからこんな感じの警告（エラー）がでる。

Warning: Abort stand-alone image build. unsupported features in 5 methods                                                                                                                              
Detailed message:                                                                                                                                                                                      
Error: Class initialization failed: io.netty.util.internal.logging.Log4JLogger                                                                                                                         
Original exception that caused the problem: java.lang.NoClassDefFoundError: org/apache/log4j/Priority 

Error: com.oracle.graal.pointsto.constraints.UnresolvedElementException: Discovered unresolved type during parsing: io.netty.util.internal.logging.Log4J2Logger.
To diagnose the issue you can use the --allow-incomplete-classpath option. The missing type is then reported at run time when it is accessed the first time.
Trace:
        at parsing io.netty.util.internal.logging.Log4J2LoggerFactory.newInstance(Log4J2LoggerFactory.java:33)
Call path from entry point to io.netty.util.internal.logging.Log4J2LoggerFactory.newInstance(String):
        at io.netty.util.internal.logging.Log4J2LoggerFactory.newInstance(Log4J2LoggerFactory.java:33)
        at io.netty.util.internal.logging.InternalLoggerFactory.getInstance(InternalLoggerFactory.java:93)

...

## v3 `Unsafe` 対応

Unsafe の対応として、Substrate VMのSubstitution（以下、代用）機能を使うので svm への依存を追加。

    <dependency>
      <groupId>com.oracle.substratevm</groupId>
      <artifactId>svm</artifactId>
      <version>1.0.0-rc15</version>
      <scope>provided</scope>
    </dependency>

そして、代用機能のためのクラスを作成。

package com.example.demo.substitution;

import com.oracle.svm.core.annotate.Alias;
import com.oracle.svm.core.annotate.RecomputeFieldValue;
import com.oracle.svm.core.annotate.TargetClass;

import static com.oracle.svm.core.annotate.RecomputeFieldValue.Kind;

@TargetClass(className = "io.netty.util.internal.PlatformDependent0")
final class Target_io_netty_util_internal_PlatformDependent0 {
  @Alias
  @RecomputeFieldValue(kind = Kind.FieldOffset, declClassName = "java.nio.Buffer", name = "address")
  private static long ADDRESS_FIELD_OFFSET;
}

@TargetClass(className = "io.netty.util.internal.CleanerJava6")
final class Target_io_netty_util_internal_CleanerJava6 {
  @Alias
  @RecomputeFieldValue(kind = Kind.FieldOffset, declClassName = "java.nio.DirectByteBuffer", name = "cleaner")
  private static long CLEANER_FIELD_OFFSET;
}

@TargetClass(className = "io.netty.util.internal.shaded.org.jctools.util.UnsafeRefArrayAccess")
final class Target_io_netty_util_internal_shaded_org_jctools_util_UnsafeRefArrayAccess {
  @Alias
  @RecomputeFieldValue(kind = Kind.ArrayIndexShift, declClass = Object[].class)
  public static int REF_ELEMENT_SHIFT;
}

public class NettySubstitution {
}

これは元記事のサンプルコードをコピペしただけで、よく分かってない。自分で書けと言われてもまだ書けない。

ロガーの問題はまだ解決してないけど、とりあえずこの時点でビルドしてみるとどうなってるかな？

❯ ./mvnw clean package

お。 Unsafe の警告が消えて、ロガーのエラーだけになってた。よし。

## v4 ロガー対応

さっきの代用機能のためのクラスに下記のクラスを追記

@TargetClass(io.netty.util.internal.logging.InternalLoggerFactory.class)
final class Target_io_netty_util_internal_logging_InternalLoggerFactory {
  @Substitute
  private static InternalLoggerFactory newDefaultFactory(String name) {
    return JdkLoggerFactory.INSTANCE;
  }
}

これは InternalLoggerFactory クラスの newDefaultFactory メソッドが JdkLoggerFactory のインスタンスを返すようにしてるってことなんだろうな。

元々は実行時にクラスの有無を見て、Log4JだとかLog4J2だとかのFactoryを返す実装になってるところを、存在するやつを固定で返すようにしてるってことか。ふむふむ。

さて、これでビルド通るかな？

❯ ./mvnw clean package

お、警告も、フォールバック的なメッセージもなく、ビルドに成功した。 target ディレクトリーの下に netty-example-http って名前（pomで指定した名前）で実行可能ファイルが生成されてる（あ、いや、実は今までも生成されてたんだけど）。実行してみる。

❯ ./target/netty-example-http
Exception in thread "main" java.lang.IllegalArgumentException: Class NioServerSocketChannel does not have a public non-arg constructor
        at io.netty.channel.ReflectiveChannelFactory.<init>(ReflectiveChannelFactory.java:36)
        at io.netty.bootstrap.AbstractBootstrap.channel(AbstractBootstrap.java:106)
        at com.example.demo.helloworld.HttpHelloWorldServer.main(HttpHelloWorldServer.java:56)
Caused by: java.lang.NoSuchMethodException: io.netty.channel.socket.nio.NioServerSocketChannel.<init>
        at java.lang.Class.getConstructor0(DynamicHub.java:3082)
        at java.lang.Class.getConstructor(DynamicHub.java:1825)
        at io.netty.channel.ReflectiveChannelFactory.<init>(ReflectiveChannelFactory.java:34)
        ... 2 more

(´・ω・`)しょぼーん

## v5 リフレクション対応

原因は HttpHelloWorldServer のこの部分

            b.group(bossGroup, workerGroup)
                .channel(NioServerSocketChannel.class)
                .handler(new LoggingHandler(LogLevel.INFO))
                .childHandler(new HttpHelloWorldServerInitializer(sslCtx));

channelのところで NioServerSocketChannel.class を渡して、このコンストラクターをリフレクションで呼び出してる。

ので、それをSubstrate VMに教えてあげる必要があるらしい。プロジェクト直下に netty_reflection_config.json という名前でこんなファイルを置いて

[
  {
    "name": "io.netty.channel.socket.nio.NioServerSocketChannel",
    "methods": [
      { "name": "<init>", "parameterTypes": [] }
    ]
  }
]

それを使うってことを native-image のパラメーターで渡す必要があるので、pomに書き加えておく。

        <configuration>
          <buildArgs>
            -H:ReflectionConfigurationFiles=${project.basedir}/netty_reflection_config.json
          </buildArgs>
          <imageName>netty-example-http</imageName>
        </configuration>

でビルドしたら・・・別の警告でた。

## v6 遅延初期化対応

Substrate VMはビルド時にクラスの初期化までしてるんだけど、それができないクラスがあるよってことみたい。で、その場合は --delay-class-initialization-to-runtime=<class-name> をつけたら良いよって書いてる。

Warning: Abort stand-alone image build. Detected a direct/mapped ByteBuffer in the image heap.
A direct ByteBuffer has a pointer to unmanaged C memory, and C memory from the image generator is not available at image run time.
A mapped ByteBuffer references a file descriptor, which is no longer open and mapped at run time.
The object was probably created by a class initializer and is reachable from a static field.
By default, all class initialization is done during native image building.
You can manually delay class initialization to image run time by using the option --delay-class-initialization-to-runtime=<class-name>.
Or you can write your own initialization methods and call them explicitly from your main entry point.

Detailed message:
Trace:  object io.netty.buffer.UnpooledByteBufAllocator$InstrumentedUnpooledUnsafeNoCleanerDirectByteBuf
        object io.netty.buffer.UnreleasableByteBuf
        method io.netty.handler.codec.http.HttpObjectEncoder.encodeChunkedContent(ChannelHandlerContext, Object, long, List)
Call path from entry point to io.netty.handler.codec.http.HttpObjectEncoder.encodeChunkedContent(ChannelHandlerContext, Object, long, List):
...

ということで、pomのbuildArgsにそのパラメーターも追加する。

        <configuration>
          <buildArgs>
            -H:ReflectionConfigurationFiles=${project.basedir}/netty_reflection_config.json
            --delay-class-initialization-to-runtime=io.netty.handler.codec.http.HttpObjectEncoder
          </buildArgs>
          <imageName>netty-example-http</imageName>
        </configuration>

で、ビルドしたら、成功したー(∩´∀｀)∩ﾜｰｲ

からの、実行も成功したー(∩´∀｀)∩ﾜｰｲ

f:id:bufferings:20190416001726p:plain:w300

じゃ、速さを比べてみるかなー。

## v7 速度比較

のために「起動できたよ！」のメッセージ直後にexitするようにする。

            System.err.println("Open your web browser and navigate to " +
                (SSL? "https" : "http") + "://127.0.0.1:" + PORT + '/');
            System.exit(0);

で、ビルドしなおして

❯ ./mvnw clean package

まずはJARで実行

❯ time java -jar target/netty-native-demo-1.0-SNAPSHOT-jar-with-dependencies.jar
Apr 16, 2019 12:22:12 AM io.netty.handler.logging.LoggingHandler channelRegistered
INFO: [id: 0xfdacf35e] REGISTERED
Apr 16, 2019 12:22:12 AM io.netty.handler.logging.LoggingHandler bind
INFO: [id: 0xfdacf35e] BIND: 0.0.0.0/0.0.0.0:8080
Open your web browser and navigate to http://127.0.0.1:8080/
Apr 16, 2019 12:22:12 AM io.netty.handler.logging.LoggingHandler channelActive
INFO: [id: 0xfdacf35e, L:/0:0:0:0:0:0:0:0:8080] ACTIVE
java -jar target/netty-native-demo-1.0-SNAPSHOT-jar-with-dependencies.jar  0.45s user 0.08s system 88% cpu 0.592 total

❯ /usr/bin/time -f "\nmaxRSS\t%MkB" java -jar target/netty-native-demo-1.0-SNAPSHOT-jar-with-dependencies.jar
Apr 16, 2019 12:22:41 AM io.netty.handler.logging.LoggingHandler channelRegistered
INFO: [id: 0x6656e56c] REGISTERED
Apr 16, 2019 12:22:41 AM io.netty.handler.logging.LoggingHandler bind
INFO: [id: 0x6656e56c] BIND: 0.0.0.0/0.0.0.0:8080
Open your web browser and navigate to http://127.0.0.1:8080/
Apr 16, 2019 12:22:41 AM io.netty.handler.logging.LoggingHandler channelActive
INFO: [id: 0x6656e56c, L:/0:0:0:0:0:0:0:0:8080] ACTIVE

maxRSS  105008kB

592msと105MBだね。何度か実行してみてもだいたいこのぐらいだった。

最後に、Native Imageを実行。

❯ time target/netty-example-http
Open your web browser and navigate to http://127.0.0.1:8080/
target/netty-example-http  0.00s user 0.01s system 89% cpu 0.011 total

~/workspace/micronaut/netty-native-demo master*
❯ /usr/bin/time -f "\nmaxRSS\t%MkB" target/netty-example-http
Open your web browser and navigate to http://127.0.0.1:8080/

maxRSS  8700kB

11msと8.7MBだね。何度か実行してみてもだいたいこのぐらいだった。

## 満足した

ちょっとだけGraalVMのNative Image周りのことに入門できた
分からないことがいっぱいあった
速かった

面白かったー！