CLOVER🍀

That was when it all began.

InfinispanのDistributed Cacheのput／getをトレースする（Local NodeがOnwerの場合）

Infinispan

少し前に、こういうエントリを書きました。

InfinispanのInterceptorの組み合わせを、Cacheの種類ごとに見てみる - CLOVER

Infinispanの各Cacheに対して、putやgetをした時にどういうInterceptorやCommmandが実行されるのか、見てみようというエントリです。

今回は、もう少し絞ってDistributed Cache（クラスタ構成）でのputやgetのトレースを、もうちょっと詳細に追ってみたいと思います。

ここでの目的は、以下です。

  • Distributed Cacheのput／getのトレース
  • 操作しているLocal NodeがキーのOwnerでなかった時に、どのような挙動をするのか見てみる
  • RPCのタイミングを見る
  • シリアライズ／デシリアライズのタイミングを見る
  • 末端でデータを保持している、DataContainerへのデータの取得／保存のタイミングを見る

このあたりを追うために、今回もBytemanのルールを仕込んでInfinispanをトレースしてみたいと思います。
※どうも書いた内容が長すぎたようなので、Local Nodeにデータがないパターンを別の記事にします

って、頑張って追うんですけど、このあたりの構造（特にInterceptorまわり）、Infinispan 9.0.0でガッツリ変わりそうですけどね！！

準備

まずは、準備作業。

ビルド定義は、このように。
build.sbt

name := "embedded-trace-distributed-putget"

version := "0.0.1-SNAPSHOT"

organization := "org.littlewings"

scalaVersion := "2.11.8"

updateOptions := updateOptions.value.withCachedResolution(true)

scalacOptions ++= Seq("-Xlint", "-deprecation", "-unchecked", "-feature")

javaOptions in Test += "-javaagent:" + System.getenv("BYTEMAN_HOME") + "/lib/byteman.jar=script:trace.btm"

fork in Test := true

parallelExecution in Test := false

libraryDependencies ++= Seq(
  "org.infinispan" % "infinispan-core" % "8.2.3.Final",
  "net.jcip" % "jcip-annotations" % "1.0" % "provided",
  "org.scalatest" %% "scalatest" % "2.2.6" % "test"
)

Java実行時に、Bytemanのルールを実行するようにしています。

Infinispanの設定は、以下の通り。
src/test/resources/infinispan.xml

<?xml version="1.0" encoding="UTF-8"?>
<infinispan
        xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
        xsi:schemaLocation="urn:infinispan:config:8.2 http://www.infinispan.org/schemas/infinispan-config-8.2.xsd"
        xmlns="urn:infinispan:config:8.2">
    <jgroups>
        <stack-file name="udp" path="jgroups.xml"/>
    </jgroups>

    <cache-container default-cache="distributedCache">
        <jmx duplicate-domains="true"/>
        <transport cluster="cluster" stack="udp"/>

        <distributed-cache name="distributedCache"/>
    </cache-container>
</infinispan>

シンプルに、Distributed Cacheをひとつだけ定義しています。

JGroupsの設定は、端折ります。

テストコード

動作確認のためのテストコードは、以下のようなものを作成しました。
src/test/scala/org/littlewings/infinispan/tracedistributedcache/TraceDistributedCachePutGetSpec.scala

package org.littlewings.infinispan.tracedistributedcache

import org.infinispan.Cache
import org.infinispan.manager.DefaultCacheManager
import org.scalatest.{FunSpec, Matchers}

class TraceDistributedCachePutGetSpec extends FunSpec with Matchers {
  describe("Trace DistributedCache Spec") {
    it("trace, self assigned key, get") {
      withCache[String, String]("distributedCache", 3) { cache =>
        val keyRange = 1 to 10
        keyRange.foreach { i =>
          println(s"===== PUT KEY = key$i START")
          cache.put(s"key$i", s"value$i")
          println(s"===== PUT KEY = key$i END")
        }

        val keys = keyRange.map(i => s"key$i").toVector

        val dm = cache.getAdvancedCache.getDistributionManager
        val self = cache.getAdvancedCache.getRpcManager.getAddress

        val pickAssignedSelfKey = keys.find(key => dm.getLocality(key).isLocal)

        pickAssignedSelfKey should not be(None)

        pickAssignedSelfKey.foreach { key =>
          println(s"===== ASSIGNED KEY = $key START =====")
          cache.get(key) should be(key.replace("key", "value"))
          println(s"===== ASSIGNED KEY = $key END =====")

          println(s"===== RE LOOKUP KEY = $key START =====")
          cache.get(key) should be(key.replace("key", "value"))
          println(s"===== RE LOOKUP KEY = $key END =====")

          val newValue = cache.get(key) + "-new"

          println(s"===== UPDATE KEY = $key START =====")
          cache.put(key, newValue)
          println(s"===== UPDATE KEY = $key END =====")
        }
      }
    }

    it("trace, not self assigned key, get") {
      withCache[String, String]("distributedCache", 3) { cache =>
        val keyRange = 1 to 10
        keyRange.foreach { i =>
          println(s"===== PUT KEY = key$i START")
          cache.put(s"key$i", s"value$i")
          println(s"===== PUT KEY = key$i END")
        }

        val keys = keyRange.map(i => s"key$i").toVector

        val dm = cache.getAdvancedCache.getDistributionManager
        val self = cache.getAdvancedCache.getRpcManager.getAddress

        val pickNotAssignedSelfKey = keys.find(key => !dm.getLocality(key).isLocal)

        pickNotAssignedSelfKey should not be(None)

        pickNotAssignedSelfKey.foreach { key =>
          println(s"===== NOT ASSIGNED KEY = $key START =====")
          cache.get(key) should be(key.replace("key", "value"))
          println(s"===== NOT ASSIGNED KEY = $key END =====")

          println(s"===== RE LOOKUP KEY = $key START =====")
          cache.get(key) should be(key.replace("key", "value"))
          println(s"===== RE LOOKUP KEY = $key END =====")

          val newValue = cache.get(key) + "-new"

          println(s"===== UPDATE KEY = $key START =====")
          cache.put(key, newValue)
          println(s"===== UPDATE KEY = $key END =====")
        }
      }
    }
  }

  protected def withCache[K, V](cacheName: String, numInstances: Int = 1)(fun: Cache[K, V] => Unit): Unit = {
    val managers = (1 to numInstances).map(_ => new DefaultCacheManager("infinispan.xml"))
    managers.foreach(_.getCache[K, V](cacheName))

    try {
      val cache = managers(0).getCache[K, V](cacheName)
      fun(cache)
    } finally {
      managers.foreach(_.getCache[K, V](cacheName).stop())
      managers.foreach(_.stop())
    }
  }
}

各テスト実行時に、InfinispanのNodeを3つ起動し、データを10件登録します。続いて、テストケースに応じてLocal Nodeにデータがあるもの、ないものをそれぞれgetします。そして、最後にすでに存在するキーに対応するエントリを更新します。

この時に、Bytemanのルールでトレースしてみて、挙動を見てみようという作戦です。

作成したBytemanルールとトレース対象

最終的に作成したルールは、こちらになります。
※長いのでリンクで

https://github.com/kazuhira-r/infinispan-getting-started/blob/master/embedded-trace-distributed-putget/trace.btm

何を追っているかというと

  • DataContainerへのput／get／peek
  • EntryLookup（というかInvocationContext）からのエントリの取得／登録（lookupEntry／putLookedUpEntry）
  • EntryFactoryからのエントリの取得／登録、DataContainerへのアクセスのタイミング（InvocationContextとDataContainerへのアクセスをラップ）
  • Marshallerを使用したシリアライズ／デシリアライズ
  • RpcManager、BaseDistributionInterceptorのサブクラスによる、RPC実行のタイミング
  • Visitorインターフェースの実装クラスによる、各種visitメソッドの実行
  • ReplicableCommandインターフェースの実装クラスによる、各種コマンドの実行

という感じです。

と、言葉だけ並べてもよくわからない感じなので、もう少し言葉を見ておきましょう。

DataContainerというのは、Infinispanの内部でデータを保持しているコンテナです。DefaultDataContainerという実装クラスがあり、

   private final ConcurrentMap<K, InternalCacheEntry<K, V>> entries;

ここにCacheのエントリが保持されています。
https://github.com/infinispan/infinispan/blob/8.2.3.Final/core/src/main/java/org/infinispan/container/DefaultDataContainer.java#L61

DataContainerはMapライクな操作を持つくらいのものなので、今回はput、get、peekメソッドにトレースを入れてデータの取得や登録のタイミングを追います。

次に、InvocationContext（とEntryLookup、EntryFactory）です。

InvocationContextというのは、InfinispanのInterceptorで各種visitメソッドを実行していく際、Interceptorをチェインしていく時に引き継がれていくインスタンスです。最終的に、Interceptorのチェインの末端にあるCommandの実装まで渡されます。

InvocationContext自体は、Cacheの実装クラスによってコマンドの呼び出し時にどのような性格のInvocationContextを生成するのかを決定します。

put。

   @SuppressWarnings("unchecked")
   final V put(K key, V value, Metadata metadata,
         EnumSet<Flag> explicitFlags, ClassLoader explicitClassLoader) {
      assertKeyValueNotNull(key, value);
      InvocationContext ctx = getInvocationContextWithImplicitTransaction(false, explicitClassLoader, 1);
      return putInternal(key, value, metadata, explicitFlags, ctx);
   }

get。

   @SuppressWarnings("unchecked")
   final V get(Object key, EnumSet<Flag> explicitFlags, ClassLoader explicitClassLoader) {
      assertKeyNotNull(key);
      InvocationContext ctx = getInvocationContextForRead(explicitClassLoader, 1);
      GetKeyValueCommand command = commandsFactory.buildGetKeyValueCommand(key, explicitFlags);
      return (V) invoker.invoke(ctx, command);
   }

https://github.com/infinispan/infinispan/blob/8.2.3.Final/core/src/main/java/org/infinispan/cache/impl/CacheImpl.java#L1110
https://github.com/infinispan/infinispan/blob/8.2.3.Final/core/src/main/java/org/infinispan/cache/impl/CacheImpl.java#L735
https://github.com/infinispan/infinispan/blob/8.2.3.Final/core/src/main/java/org/infinispan/cache/impl/CacheImpl.java#L409
https://github.com/infinispan/infinispan/blob/8.2.3.Final/core/src/main/java/org/infinispan/cache/impl/CacheImpl.java#L742

Write用、Read用といった感じで。

で、末端で実行されるCommand、例えばCache#get時に呼び出されるGetKeyValueCommandというクラスは、実はDataContainerへのアクセスは行いません。このCommandに到達するまでに、InterceotprのチェインのどこかでInvocationContextにエントリが設定されており、それを返すといった処理を行います。

GetCommand#perform。
https://github.com/infinispan/infinispan/blob/8.2.3.Final/core/src/main/java/org/infinispan/commands/read/GetKeyValueCommand.java#L53

   @Override
   public Object perform(InvocationContext ctx) throws Throwable {
      CacheEntry entry = ctx.lookupEntry(key);

PutKeyValueCommand#perform。
https://github.com/infinispan/infinispan/blob/8.2.3.Final/core/src/main/java/org/infinispan/commands/write/PutKeyValueCommand.java#L98

   @Override
   public Object perform(InvocationContext ctx) throws Throwable {
      // It's not worth looking up the entry if we're never going to apply the change.
      if (valueMatcher == ValueMatcher.MATCH_NEVER) {
         successful = false;
         return null;
      }
      MVCCEntry e = (MVCCEntry) ctx.lookupEntry(key);

この過程で、誰がInvocationContext（EntryLookup）にエントリを設定するのかを追う、という感じですね。

Marshallerについては、単純にシリアライズ／デシリアライズのタイミングを見てみるだけです。

あとは、気になるところとしてRPCの実行タイミングを見るために、RpcManagerとBaseDistributionInterceptorに対してトレースを仕込みます。Interceptorでは、他Nodeへのアクセスの際には、これらのクラスの機能を使っているようなので。これで、ネットワーク通信のタイミングを見てみようという魂胆です。

実行してみる

それでは、実行して結果をトレースしてみましょう。

Local Nodeにエントリがある場合

コード上、最初にエントリをputしてからgetするようになっているのですが、結果はgetから見てみましょう。

getのトレース結果。
※一部端折っているのと、見やすいようにインデントを入れています

今回は、Local Nodeに割り当てられたキーとして、「key1」を選択したようです。

===== ASSIGNED KEY = key1 START =====
[Interceptor] DistributionBulkInterceptor:visitGetKeyValueCommand, entry
  [Interceptor] InvocationContextInterceptor:visitGetKeyValueCommand, entry
    [Interceptor] CacheMgmtInterceptor:visitGetKeyValueCommand, entry
      [Interceptor] StateTransferInterceptor:visitGetKeyValueCommand, entry
        [Interceptor] NonTransactionalLockingInterceptor:visitGetKeyValueCommand, entry
          [Interceptor] EntryWrappingInterceptor:visitGetKeyValueCommand, entry
            [EntryFactory] EntryFactoryImpl:wrapEntryForReading, entry
              [EntryFactory] EntryFactoryImpl:getFromContext, entry
                [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
              [EntryFactory] EntryFactoryImpl:getFromContext, exit
              [EntryFactory] EntryFactoryImpl:getFromContainer, entry
                [DataContainer] DefaultDataContainer:get, entry
                [DataContainer] DefaultDataContainer:get, exit
              [EntryFactory] EntryFactoryImpl:getFromContainer, exit
              [EntryLookup] SingleKeyNonTxInvocationContext:putLookedUpEntry, entry
              [EntryLookup] SingleKeyNonTxInvocationContext:putLookedUpEntry, exit
            [EntryFactory] EntryFactoryImpl:wrapEntryForReading, exit
            [Interceptor] NonTxDistributionInterceptor:visitGetKeyValueCommand, entry
              [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
              [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
              [Interceptor] CallInterceptor:visitGetKeyValueCommand, entry
                [Command] GetKeyValueCommand:perform, entry
                  [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                  [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
                [Command] GetKeyValueCommand:perform, exit
              [Interceptor] CallInterceptor:visitGetKeyValueCommand, exit
            [Interceptor] NonTxDistributionInterceptor:visitGetKeyValueCommand, exit
          [Interceptor] EntryWrappingInterceptor:visitGetKeyValueCommand, exit
        [Interceptor] NonTransactionalLockingInterceptor:visitGetKeyValueCommand, exit
      [Interceptor] StateTransferInterceptor:visitGetKeyValueCommand, exit
    [Interceptor] CacheMgmtInterceptor:visitGetKeyValueCommand, exit
  [Interceptor] InvocationContextInterceptor:visitGetKeyValueCommand, exit
[Interceptor] DistributionBulkInterceptor:visitGetKeyValueCommand, exit
===== ASSIGNED KEY = key1 END =====

これを見ると、EntryWrappingInterceptor:visitGetKeyValueCommandで、InvocationContextにエントリがなかったら、DataContainerにエントリを取りに行っている感じのように見えますね。そして、取得したエントリInvocationContext#putLookedUpEntryで登録する、と。

          [Interceptor] EntryWrappingInterceptor:visitGetKeyValueCommand, entry
            [EntryFactory] EntryFactoryImpl:wrapEntryForReading, entry
              [EntryFactory] EntryFactoryImpl:getFromContext, entry
                [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
              [EntryFactory] EntryFactoryImpl:getFromContext, exit
              [EntryFactory] EntryFactoryImpl:getFromContainer, entry
                [DataContainer] DefaultDataContainer:get, entry
                [DataContainer] DefaultDataContainer:get, exit
              [EntryFactory] EntryFactoryImpl:getFromContainer, exit
              [EntryLookup] SingleKeyNonTxInvocationContext:putLookedUpEntry, entry
              [EntryLookup] SingleKeyNonTxInvocationContext:putLookedUpEntry, exit
            [EntryFactory] EntryFactoryImpl:wrapEntryForReading, exit

デシリアライズは出てきませんね、と。

なので、GetKeyValueCommand:performでは単純にInvocationContextから結果を取得しているだけです。

                [Command] GetKeyValueCommand:perform, entry
                  [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                  [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
                [Command] GetKeyValueCommand:perform, exit

では、登録時（put）はどうでしょう。

こんな感じになりました。

===== PUT KEY = key1 START
[Interceptor] DistributionBulkInterceptor:visitPutKeyValueCommand, entry
  [Interceptor] InvocationContextInterceptor:visitPutKeyValueCommand, entry
    [Interceptor] CacheMgmtInterceptor:visitPutKeyValueCommand, entry
      [Interceptor] StateTransferInterceptor:visitPutKeyValueCommand, entry
        [Interceptor] NonTransactionalLockingInterceptor:visitPutKeyValueCommand, entry
          [Interceptor] EntryWrappingInterceptor:visitPutKeyValueCommand, entry
            [Interceptor] NonTxDistributionInterceptor:visitPutKeyValueCommand, entry
              [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
              [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
              [Interceptor] CallInterceptor:visitPutKeyValueCommand, entry
                [Command] PutKeyValueCommand:perform, entry
                  [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                  [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
                [Command] PutKeyValueCommand:perform, exit
              [Interceptor] CallInterceptor:visitPutKeyValueCommand, exit
              [RpcManager] RpcManagerImpl:invokeRemotely, entry
                [Marshaller] GlobalMarshaller:objectToBuffer, entry
                [Marshaller] GlobalMarshaller:objectToBuffer, exit
                [Marshaller] GlobalMarshaller:objectFromByteBuffer, entry
                [Marshaller] GlobalMarshaller:objectFromByteBuffer, exit
                [Command] SingleRpcCommand:perform, entry
                  [Interceptor] DistributionBulkInterceptor:visitPutKeyValueCommand, entry
                    [Interceptor] InvocationContextInterceptor:visitPutKeyValueCommand, entry
                      [Interceptor] CacheMgmtInterceptor:visitPutKeyValueCommand, entry
                        [Interceptor] StateTransferInterceptor:visitPutKeyValueCommand, entry
                          [Interceptor] NonTransactionalLockingInterceptor:visitPutKeyValueCommand, entry
                            [Interceptor] EntryWrappingInterceptor:visitPutKeyValueCommand, entry
                              [EntryFactory] EntryFactoryImpl:wrapEntryForWriting, entry
                                [EntryFactory] EntryFactoryImpl:getFromContext, entry
                                  [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                                  [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
                                [EntryFactory] EntryFactoryImpl:getFromContext, exit
                                [EntryFactory] EntryFactoryImpl:getFromContainer, entry
                                  [DataContainer] DefaultDataContainer:peek, entry
                                  [DataContainer] DefaultDataContainer:peek, exit
                                [EntryFactory] EntryFactoryImpl:getFromContainer, exit
                                [EntryLookup] SingleKeyNonTxInvocationContext:putLookedUpEntry, entry
                                [EntryLookup] SingleKeyNonTxInvocationContext:putLookedUpEntry, exit
                              [EntryFactory] EntryFactoryImpl:wrapEntryForWriting, exit
                              [Interceptor] NonTxDistributionInterceptor:visitPutKeyValueCommand, entry
                                [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                                [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
                                [Interceptor] CallInterceptor:visitPutKeyValueCommand, entry
                                  [Command] PutKeyValueCommand:perform, entry
                                    [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                                    [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
                                  [Command] PutKeyValueCommand:perform, exit
                                [Interceptor] CallInterceptor:visitPutKeyValueCommand, exit
                                [RpcManager] RpcManagerImpl:invokeRemotely, entry
                                  [Marshaller] GlobalMarshaller:objectToBuffer, entry
                                  [Marshaller] GlobalMarshaller:objectToBuffer, exit
                                  [Marshaller] GlobalMarshaller:objectFromByteBuffer, entry
                                  [Marshaller] GlobalMarshaller:objectFromByteBuffer, exit
                                  [Command] SingleRpcCommand:perform, entry
                                    [Interceptor] DistributionBulkInterceptor:visitPutKeyValueCommand, entry
                                      [Interceptor] InvocationContextInterceptor:visitPutKeyValueCommand, entry
                                        [Interceptor] CacheMgmtInterceptor:visitPutKeyValueCommand, entry
                                          [Interceptor] StateTransferInterceptor:visitPutKeyValueCommand, entry
                                            [Interceptor] NonTransactionalLockingInterceptor:visitPutKeyValueCommand, entry
                                              [Interceptor] EntryWrappingInterceptor:visitPutKeyValueCommand, entry
                                                [EntryFactory] EntryFactoryImpl:wrapEntryForWriting, entry
                                                  [EntryFactory] EntryFactoryImpl:getFromContext, entry
                                                    [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                                                    [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
                                                  [EntryFactory] EntryFactoryImpl:getFromContext, exit
                                                  [EntryFactory] EntryFactoryImpl:getFromContainer, entry
                                                    [DataContainer] DefaultDataContainer:peek, entry
                                                    [DataContainer] DefaultDataContainer:peek, exit
                                                  [EntryFactory] EntryFactoryImpl:getFromContainer, exit
                                                  [EntryLookup] SingleKeyNonTxInvocationContext:putLookedUpEntry, entry
                                                  [EntryLookup] SingleKeyNonTxInvocationContext:putLookedUpEntry, exit
                                                [EntryFactory] EntryFactoryImpl:wrapEntryForWriting, exit
                                                [Interceptor] NonTxDistributionInterceptor:visitPutKeyValueCommand, entry
                                                  [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                                                  [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
                                                  [Interceptor] CallInterceptor:visitPutKeyValueCommand, entry
                                                    [Command] PutKeyValueCommand:perform, entry
                                                      [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                                                      [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
                                                    [Command] PutKeyValueCommand:perform, exit
                                                  [Interceptor] CallInterceptor:visitPutKeyValueCommand, exit
                                                [Interceptor] NonTxDistributionInterceptor:visitPutKeyValueCommand, exit
                                                [DataContainer] DefaultDataContainer:peek, entry
                                                [DataContainer] DefaultDataContainer:peek, exit
                                                [DataContainer] DefaultDataContainer:put, entry
                                                [DataContainer] DefaultDataContainer:put, exit
                                              [Interceptor] EntryWrappingInterceptor:visitPutKeyValueCommand, exit
                                            [Interceptor] NonTransactionalLockingInterceptor:visitPutKeyValueCommand, exit
                                          [Interceptor] StateTransferInterceptor:visitPutKeyValueCommand, exit
                                        [Interceptor] CacheMgmtInterceptor:visitPutKeyValueCommand, exit
                                      [Interceptor] InvocationContextInterceptor:visitPutKeyValueCommand, exit
                                    [Interceptor] DistributionBulkInterceptor:visitPutKeyValueCommand, exit
                                  [Command] SingleRpcCommand:perform, exit
                                  [Marshaller] GlobalMarshaller:objectToBuffer, entry
                                  [Marshaller] GlobalMarshaller:objectToBuffer, exit
                                  [Marshaller] GlobalMarshaller:objectFromByteBuffer, entry
                                  [Marshaller] GlobalMarshaller:objectFromByteBuffer, exit
                                [RpcManager] RpcManagerImpl:invokeRemotely, exit
                              [Interceptor] NonTxDistributionInterceptor:visitPutKeyValueCommand, exit
                              [DataContainer] DefaultDataContainer:peek, entry
                              [DataContainer] DefaultDataContainer:peek, exit
                              [DataContainer] DefaultDataContainer:put, entry
                              [DataContainer] DefaultDataContainer:put, exit
                            [Interceptor] EntryWrappingInterceptor:visitPutKeyValueCommand, exit
                          [Interceptor] NonTransactionalLockingInterceptor:visitPutKeyValueCommand, exit
                        [Interceptor] StateTransferInterceptor:visitPutKeyValueCommand, exit
                      [Interceptor] CacheMgmtInterceptor:visitPutKeyValueCommand, exit
                    [Interceptor] InvocationContextInterceptor:visitPutKeyValueCommand, exit
                  [Interceptor] DistributionBulkInterceptor:visitPutKeyValueCommand, exit
                [Command] SingleRpcCommand:perform, exit
                [Marshaller] GlobalMarshaller:objectToBuffer, entry
                [Marshaller] GlobalMarshaller:objectToBuffer, exit
                [Marshaller] GlobalMarshaller:objectFromByteBuffer, entry
                [Marshaller] GlobalMarshaller:objectFromByteBuffer, exit
              [RpcManager] RpcManagerImpl:invokeRemotely, exit
            [Interceptor] NonTxDistributionInterceptor:visitPutKeyValueCommand, exit
          [Interceptor] EntryWrappingInterceptor:visitPutKeyValueCommand, exit
        [Interceptor] NonTransactionalLockingInterceptor:visitPutKeyValueCommand, exit
      [Interceptor] StateTransferInterceptor:visitPutKeyValueCommand, exit
    [Interceptor] CacheMgmtInterceptor:visitPutKeyValueCommand, exit
  [Interceptor] InvocationContextInterceptor:visitPutKeyValueCommand, exit
[Interceptor] DistributionBulkInterceptor:visitPutKeyValueCommand, exit
===== PUT KEY = key1 END

長！！

なんか、2回RPCが投げられていますね。はて？

RPCの実行を指示しているのは、このあたりです。
https://github.com/infinispan/infinispan/blob/8.2.3.Final/core/src/main/java/org/infinispan/interceptors/distribution/BaseDistributionInterceptor.java#L279

RPCの実行前後には、Marshallerが呼び出され、シリアライズ／デシリアライズが行われるっぽい感じのことが読み取れます。

また、トレース結果からはわからないのですが、直接DataContainer#putを呼び出しているのは今回はReadCommittedEntryのようです。
https://github.com/infinispan/infinispan/blob/8.2.3.Final/core/src/main/java/org/infinispan/container/entries/ReadCommittedEntry.java#L168

そして、コミット指示をしているのはEntryWrappingInterceptorですと。
https://github.com/infinispan/infinispan/blob/8.2.3.Final/core/src/main/java/org/infinispan/interceptors/EntryWrappingInterceptor.java#L530

あくまでPutKeyValueCommandはInvocationContextを操作しているだけで、DataContainerへの反映はInterceptorみたいですね。

                              [Interceptor] NonTxDistributionInterceptor:visitPutKeyValueCommand, exit
                              [DataContainer] DefaultDataContainer:peek, entry
                              [DataContainer] DefaultDataContainer:peek, exit
                              [DataContainer] DefaultDataContainer:put, entry
                              [DataContainer] DefaultDataContainer:put, exit
                            [Interceptor] EntryWrappingInterceptor:visitPutKeyValueCommand, exit

InvocationContextへのエントリの登録は、EntryWrappingInterceptorでの処理内で行われる感じですね。

                            [Interceptor] EntryWrappingInterceptor:visitPutKeyValueCommand, entry
                              [EntryFactory] EntryFactoryImpl:wrapEntryForWriting, entry
                                [EntryFactory] EntryFactoryImpl:getFromContext, entry
                                  [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                                  [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
                                [EntryFactory] EntryFactoryImpl:getFromContext, exit
                                [EntryFactory] EntryFactoryImpl:getFromContainer, entry
                                  [DataContainer] DefaultDataContainer:peek, entry
                                  [DataContainer] DefaultDataContainer:peek, exit
                                [EntryFactory] EntryFactoryImpl:getFromContainer, exit
                                [EntryLookup] SingleKeyNonTxInvocationContext:putLookedUpEntry, entry
                                [EntryLookup] SingleKeyNonTxInvocationContext:putLookedUpEntry, exit
                              [EntryFactory] EntryFactoryImpl:wrapEntryForWriting, exit

では、エントリを更新してみます。

===== UPDATE KEY = key1 START =====
[Interceptor] DistributionBulkInterceptor:visitPutKeyValueCommand, entry
  [Interceptor] InvocationContextInterceptor:visitPutKeyValueCommand, entry
    [Interceptor] CacheMgmtInterceptor:visitPutKeyValueCommand, entry
      [Interceptor] StateTransferInterceptor:visitPutKeyValueCommand, entry
        [Interceptor] NonTransactionalLockingInterceptor:visitPutKeyValueCommand, entry
          [Interceptor] EntryWrappingInterceptor:visitPutKeyValueCommand, entry
            [Interceptor] NonTxDistributionInterceptor:visitPutKeyValueCommand, entry
              [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
              [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
              [Interceptor] CallInterceptor:visitPutKeyValueCommand, entry
                [Command] PutKeyValueCommand:perform, entry
                  [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                  [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
                [Command] PutKeyValueCommand:perform, exit
              [Interceptor] CallInterceptor:visitPutKeyValueCommand, exit
              [RpcManager] RpcManagerImpl:invokeRemotely, entry
                [Marshaller] GlobalMarshaller:objectToBuffer, entry
                [Marshaller] GlobalMarshaller:objectToBuffer, exit
                [Marshaller] GlobalMarshaller:objectFromByteBuffer, entry
                [Marshaller] GlobalMarshaller:objectFromByteBuffer, exit
                [Command] SingleRpcCommand:perform, entry
                  [Interceptor] DistributionBulkInterceptor:visitPutKeyValueCommand, entry
                    [Interceptor] InvocationContextInterceptor:visitPutKeyValueCommand, entry
                      [Interceptor] CacheMgmtInterceptor:visitPutKeyValueCommand, entry
                        [Interceptor] StateTransferInterceptor:visitPutKeyValueCommand, entry
                          [Interceptor] NonTransactionalLockingInterceptor:visitPutKeyValueCommand, entry
                            [Interceptor] EntryWrappingInterceptor:visitPutKeyValueCommand, entry
                              [EntryFactory] EntryFactoryImpl:wrapEntryForWriting, entry
                                [EntryFactory] EntryFactoryImpl:getFromContext, entry
                                  [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                                  [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
                                [EntryFactory] EntryFactoryImpl:getFromContext, exit
                                [EntryFactory] EntryFactoryImpl:getFromContainer, entry
                                  [DataContainer] DefaultDataContainer:peek, entry
                                  [DataContainer] DefaultDataContainer:peek, exit
                                [EntryFactory] EntryFactoryImpl:getFromContainer, exit
                                [EntryLookup] SingleKeyNonTxInvocationContext:putLookedUpEntry, entry
                                [EntryLookup] SingleKeyNonTxInvocationContext:putLookedUpEntry, exit
                              [EntryFactory] EntryFactoryImpl:wrapEntryForWriting, exit
                              [Interceptor] NonTxDistributionInterceptor:visitPutKeyValueCommand, entry
                                [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                                [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
                                [Interceptor] CallInterceptor:visitPutKeyValueCommand, entry
                                  [Command] PutKeyValueCommand:perform, entry
                                    [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                                    [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
                                  [Command] PutKeyValueCommand:perform, exit
                                [Interceptor] CallInterceptor:visitPutKeyValueCommand, exit
                                [RpcManager] RpcManagerImpl:invokeRemotely, entry
                                  [Marshaller] GlobalMarshaller:objectToBuffer, entry
                                  [Marshaller] GlobalMarshaller:objectToBuffer, exit
                                  [Marshaller] GlobalMarshaller:objectFromByteBuffer, entry
                                  [Marshaller] GlobalMarshaller:objectFromByteBuffer, exit
                                  [Command] SingleRpcCommand:perform, entry
                                    [Interceptor] DistributionBulkInterceptor:visitPutKeyValueCommand, entry
                                      [Interceptor] InvocationContextInterceptor:visitPutKeyValueCommand, entry
                                        [Interceptor] CacheMgmtInterceptor:visitPutKeyValueCommand, entry
                                          [Interceptor] StateTransferInterceptor:visitPutKeyValueCommand, entry
                                            [Interceptor] NonTransactionalLockingInterceptor:visitPutKeyValueCommand, entry
                                              [Interceptor] EntryWrappingInterceptor:visitPutKeyValueCommand, entry
                                                [EntryFactory] EntryFactoryImpl:wrapEntryForWriting, entry
                                                  [EntryFactory] EntryFactoryImpl:getFromContext, entry
                                                    [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                                                    [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
                                                  [EntryFactory] EntryFactoryImpl:getFromContext, exit
                                                  [EntryFactory] EntryFactoryImpl:getFromContainer, entry
                                                    [DataContainer] DefaultDataContainer:peek, entry
                                                    [DataContainer] DefaultDataContainer:peek, exit
                                                  [EntryFactory] EntryFactoryImpl:getFromContainer, exit
                                                    [EntryLookup] SingleKeyNonTxInvocationContext:putLookedUpEntry, entry
                                                    [EntryLookup] SingleKeyNonTxInvocationContext:putLookedUpEntry, exit
                                                  [EntryFactory] EntryFactoryImpl:wrapEntryForWriting, exit
                                                  [Interceptor] NonTxDistributionInterceptor:visitPutKeyValueCommand, entry
                                                    [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                                                    [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
                                                    [Interceptor] CallInterceptor:visitPutKeyValueCommand, entry
                                                      [Command] PutKeyValueCommand:perform, entry
                                                        [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                                                        [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
                                                      [Command] PutKeyValueCommand:perform, exit
                                                    [Interceptor] CallInterceptor:visitPutKeyValueCommand, exit
                                                  [Interceptor] NonTxDistributionInterceptor:visitPutKeyValueCommand, exit
                                                  [DataContainer] DefaultDataContainer:peek, entry
                                                  [DataContainer] DefaultDataContainer:peek, exit
                                                  [DataContainer] DefaultDataContainer:put, entry
                                                  [DataContainer] DefaultDataContainer:put, exit
                                                [Interceptor] EntryWrappingInterceptor:visitPutKeyValueCommand, exit
                                              [Interceptor] NonTransactionalLockingInterceptor:visitPutKeyValueCommand, exit
                                            [Interceptor] StateTransferInterceptor:visitPutKeyValueCommand, exit
                                          [Interceptor] CacheMgmtInterceptor:visitPutKeyValueCommand, exit
                                        [Interceptor] InvocationContextInterceptor:visitPutKeyValueCommand, exit
                                      [Interceptor] DistributionBulkInterceptor:visitPutKeyValueCommand, exit
                                    [Command] SingleRpcCommand:perform, exit
                                    [Marshaller] GlobalMarshaller:objectToBuffer, entry
                                    [Marshaller] GlobalMarshaller:objectToBuffer, exit
                                    [Marshaller] GlobalMarshaller:objectFromByteBuffer, entry
                                    [Marshaller] GlobalMarshaller:objectFromByteBuffer, exit
                                  [RpcManager] RpcManagerImpl:invokeRemotely, exit
                                [Interceptor] NonTxDistributionInterceptor:visitPutKeyValueCommand, exit
                                [DataContainer] DefaultDataContainer:peek, entry
                                [DataContainer] DefaultDataContainer:peek, exit
                                [DataContainer] DefaultDataContainer:put, entry
                              [DataContainer] DefaultDataContainer:put, exit
                            [Interceptor] EntryWrappingInterceptor:visitPutKeyValueCommand, exit
                          [Interceptor] NonTransactionalLockingInterceptor:visitPutKeyValueCommand, exit
                        [Interceptor] StateTransferInterceptor:visitPutKeyValueCommand, exit
                      [Interceptor] CacheMgmtInterceptor:visitPutKeyValueCommand, exit
                    [Interceptor] InvocationContextInterceptor:visitPutKeyValueCommand, exit
                  [Interceptor] DistributionBulkInterceptor:visitPutKeyValueCommand, exit
                [Command] SingleRpcCommand:perform, exit
                [Marshaller] GlobalMarshaller:objectToBuffer, entry
                [Marshaller] GlobalMarshaller:objectToBuffer, exit
                [Marshaller] GlobalMarshaller:objectFromByteBuffer, entry
                [Marshaller] GlobalMarshaller:objectFromByteBuffer, exit
              [RpcManager] RpcManagerImpl:invokeRemotely, exit
            [Interceptor] NonTxDistributionInterceptor:visitPutKeyValueCommand, exit
          [Interceptor] EntryWrappingInterceptor:visitPutKeyValueCommand, exit
        [Interceptor] NonTransactionalLockingInterceptor:visitPutKeyValueCommand, exit
      [Interceptor] StateTransferInterceptor:visitPutKeyValueCommand, exit
    [Interceptor] CacheMgmtInterceptor:visitPutKeyValueCommand, exit
  [Interceptor] InvocationContextInterceptor:visitPutKeyValueCommand, exit
[Interceptor] DistributionBulkInterceptor:visitPutKeyValueCommand, exit
===== UPDATE KEY = key1 END =====

あれ？そんなに変わらない？

どうも、エントリのOwnerがPrimaryかそうでないかで、挙動が変わりそうな気がします。

そこで、キーの抽出条件を変更。

        // val pickAssignedSelfKey = keys.find(key => dm.getLocality(key).isLocal)
        val pickAssignedSelfKey = keys.find(key => dm.getLocality(key).isLocal && dm.getPrimaryLocation(key) == self)

これで、再度実行してみます。getの時の挙動は変わらないので、初回のputと更新時を追ってみます。
※今度はキーが「key2」に変わりました…

登録時。

===== PUT KEY = key2 START
[Interceptor] DistributionBulkInterceptor:visitPutKeyValueCommand, entry
  [Interceptor] InvocationContextInterceptor:visitPutKeyValueCommand, entry
    [Interceptor] CacheMgmtInterceptor:visitPutKeyValueCommand, entry
      [Interceptor] StateTransferInterceptor:visitPutKeyValueCommand, entry
        [Interceptor] NonTransactionalLockingInterceptor:visitPutKeyValueCommand, entry
          [Interceptor] EntryWrappingInterceptor:visitPutKeyValueCommand, entry
            [EntryFactory] EntryFactoryImpl:wrapEntryForWriting, entry
              [EntryFactory] EntryFactoryImpl:getFromContext, entry
                [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
              [EntryFactory] EntryFactoryImpl:getFromContext, exit
              [EntryFactory] EntryFactoryImpl:getFromContainer, entry
                [DataContainer] DefaultDataContainer:peek, entry
                [DataContainer] DefaultDataContainer:peek, exit
              [EntryFactory] EntryFactoryImpl:getFromContainer, exit
            [EntryLookup] SingleKeyNonTxInvocationContext:putLookedUpEntry, entry
            [EntryLookup] SingleKeyNonTxInvocationContext:putLookedUpEntry, exit
          [EntryFactory] EntryFactoryImpl:wrapEntryForWriting, exit
          [Interceptor] NonTxDistributionInterceptor:visitPutKeyValueCommand, entry
            [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
            [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
            [Interceptor] CallInterceptor:visitPutKeyValueCommand, entry
              [Command] PutKeyValueCommand:perform, entry
                [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
              [Command] PutKeyValueCommand:perform, exit
            [Interceptor] CallInterceptor:visitPutKeyValueCommand, exit
            [RpcManager] RpcManagerImpl:invokeRemotely, entry
              [Marshaller] GlobalMarshaller:objectToBuffer, entry
              [Marshaller] GlobalMarshaller:objectToBuffer, exit
              [Marshaller] GlobalMarshaller:objectFromByteBuffer, entry
              [Marshaller] GlobalMarshaller:objectFromByteBuffer, exit
              [Command] SingleRpcCommand:perform, entry
                [Interceptor] DistributionBulkInterceptor:visitPutKeyValueCommand, entry
                  [Interceptor] InvocationContextInterceptor:visitPutKeyValueCommand, entry
                    [Interceptor] CacheMgmtInterceptor:visitPutKeyValueCommand, entry
                      [Interceptor] StateTransferInterceptor:visitPutKeyValueCommand, entry
                        [Interceptor] NonTransactionalLockingInterceptor:visitPutKeyValueCommand, entry
                          [Interceptor] EntryWrappingInterceptor:visitPutKeyValueCommand, entry
                            [EntryFactory] EntryFactoryImpl:wrapEntryForWriting, entry
                              [EntryFactory] EntryFactoryImpl:getFromContext, entry
                                [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                                [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
                              [EntryFactory] EntryFactoryImpl:getFromContext, exit
                              [EntryFactory] EntryFactoryImpl:getFromContainer, entry
                                [DataContainer] DefaultDataContainer:peek, entry
                                [DataContainer] DefaultDataContainer:peek, exit
                              [EntryFactory] EntryFactoryImpl:getFromContainer, exit
                              [EntryLookup] SingleKeyNonTxInvocationContext:putLookedUpEntry, entry
                              [EntryLookup] SingleKeyNonTxInvocationContext:putLookedUpEntry, exit
                            [EntryFactory] EntryFactoryImpl:wrapEntryForWriting, exit
                              [Interceptor] NonTxDistributionInterceptor:visitPutKeyValueCommand, entry
                                [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                                [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
                                [Interceptor] CallInterceptor:visitPutKeyValueCommand, entry
                                  [Command] PutKeyValueCommand:perform, entry
                                    [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                                    [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
                                  [Command] PutKeyValueCommand:perform, exit
                                [Interceptor] CallInterceptor:visitPutKeyValueCommand, exit
                                [Interceptor] NonTxDistributionInterceptor:visitPutKeyValueCommand, exit
                                [DataContainer] DefaultDataContainer:peek, entry
                                [DataContainer] DefaultDataContainer:peek, exit
                                [DataContainer] DefaultDataContainer:put, entry
                                [DataContainer] DefaultDataContainer:put, exit
                              [Interceptor] EntryWrappingInterceptor:visitPutKeyValueCommand, exit
                            [Interceptor] NonTransactionalLockingInterceptor:visitPutKeyValueCommand, exit
                          [Interceptor] StateTransferInterceptor:visitPutKeyValueCommand, exit
                        [Interceptor] CacheMgmtInterceptor:visitPutKeyValueCommand, exit
                      [Interceptor] InvocationContextInterceptor:visitPutKeyValueCommand, exit
                    [Interceptor] DistributionBulkInterceptor:visitPutKeyValueCommand, exit
                  [Command] SingleRpcCommand:perform, exit
                [Marshaller] GlobalMarshaller:objectToBuffer, entry
                [Marshaller] GlobalMarshaller:objectToBuffer, exit
                [Marshaller] GlobalMarshaller:objectFromByteBuffer, entry
                [Marshaller] GlobalMarshaller:objectFromByteBuffer, exit
              [RpcManager] RpcManagerImpl:invokeRemotely, exit
            [Interceptor] NonTxDistributionInterceptor:visitPutKeyValueCommand, exit
            [DataContainer] DefaultDataContainer:peek, entry
            [DataContainer] DefaultDataContainer:peek, exit
            [DataContainer] DefaultDataContainer:put, entry
            [DataContainer] DefaultDataContainer:put, exit
          [Interceptor] EntryWrappingInterceptor:visitPutKeyValueCommand, exit
        [Interceptor] NonTransactionalLockingInterceptor:visitPutKeyValueCommand, exit
      [Interceptor] StateTransferInterceptor:visitPutKeyValueCommand, exit
    [Interceptor] CacheMgmtInterceptor:visitPutKeyValueCommand, exit
  [Interceptor] InvocationContextInterceptor:visitPutKeyValueCommand, exit
[Interceptor] DistributionBulkInterceptor:visitPutKeyValueCommand, exit
===== PUT KEY = key2 END

なんか、だいぶすっきりしてDataContainerへのアクセスが早い段階で登場するようになりましたね？

どうなってるんでしょう？ってことで、もう少し追ってみると、やっぱりエントリのOwnerがPrimaryかそうでないかで挙動が変わるようです。
https://github.com/infinispan/infinispan/blob/8.2.3.Final/core/src/main/java/org/infinispan/interceptors/EntryWrappingInterceptor.java#L234-L238

         if (isUsingLockDelegation || isTransactional) {
            result = cdl.localNodeIsPrimaryOwner(key) || (cdl.localNodeIsOwner(key) && !ctx.isOriginLocal());
         } else {
            result = cdl.localNodeIsOwner(key);
         }

なるほど。ということは、先ほどの例だと、Local Nodeにバックアップがあった状態で実行していたということですね。

更新時。

===== UPDATE KEY = key2 START =====
[Interceptor] DistributionBulkInterceptor:visitPutKeyValueCommand, entry
  [Interceptor] InvocationContextInterceptor:visitPutKeyValueCommand, entry
    [Interceptor] CacheMgmtInterceptor:visitPutKeyValueCommand, entry
      [Interceptor] StateTransferInterceptor:visitPutKeyValueCommand, entry
        [Interceptor] NonTransactionalLockingInterceptor:visitPutKeyValueCommand, entry
          [Interceptor] EntryWrappingInterceptor:visitPutKeyValueCommand, entry
            [EntryFactory] EntryFactoryImpl:wrapEntryForWriting, entry
              [EntryFactory] EntryFactoryImpl:getFromContext, entry
                [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
              [EntryFactory] EntryFactoryImpl:getFromContext, exit
              [EntryFactory] EntryFactoryImpl:getFromContainer, entry
                [DataContainer] DefaultDataContainer:peek, entry
                [DataContainer] DefaultDataContainer:peek, exit
              [EntryFactory] EntryFactoryImpl:getFromContainer, exit
              [EntryLookup] SingleKeyNonTxInvocationContext:putLookedUpEntry, entry
              [EntryLookup] SingleKeyNonTxInvocationContext:putLookedUpEntry, exit
            [EntryFactory] EntryFactoryImpl:wrapEntryForWriting, exit
            [Interceptor] NonTxDistributionInterceptor:visitPutKeyValueCommand, entry
              [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
              [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
              [Interceptor] CallInterceptor:visitPutKeyValueCommand, entry
                [Command] PutKeyValueCommand:perform, entry
                  [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                  [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
                [Command] PutKeyValueCommand:perform, exit
              [Interceptor] CallInterceptor:visitPutKeyValueCommand, exit
              [RpcManager] RpcManagerImpl:invokeRemotely, entry
                [Marshaller] GlobalMarshaller:objectToBuffer, entry
                [Marshaller] GlobalMarshaller:objectToBuffer, exit
                [Marshaller] GlobalMarshaller:objectFromByteBuffer, entry
                [Marshaller] GlobalMarshaller:objectFromByteBuffer, exit
                [Command] SingleRpcCommand:perform, entry
                  [Interceptor] DistributionBulkInterceptor:visitPutKeyValueCommand, entry
                    [Interceptor] InvocationContextInterceptor:visitPutKeyValueCommand, entry
                      [Interceptor] CacheMgmtInterceptor:visitPutKeyValueCommand, entry
                        [Interceptor] StateTransferInterceptor:visitPutKeyValueCommand, entry
                          [Interceptor] NonTransactionalLockingInterceptor:visitPutKeyValueCommand, entry
                            [Interceptor] EntryWrappingInterceptor:visitPutKeyValueCommand, entry
                              [EntryFactory] EntryFactoryImpl:wrapEntryForWriting, entry
                                [EntryFactory] EntryFactoryImpl:getFromContext, entry
                                  [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                                  [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
                                [EntryFactory] EntryFactoryImpl:getFromContext, exit
                                [EntryFactory] EntryFactoryImpl:getFromContainer, entry
                                  [DataContainer] DefaultDataContainer:peek, entry
                                  [DataContainer] DefaultDataContainer:peek, exit
                                [EntryFactory] EntryFactoryImpl:getFromContainer, exit
                                  [EntryLookup] SingleKeyNonTxInvocationContext:putLookedUpEntry, entry
                                  [EntryLookup] SingleKeyNonTxInvocationContext:putLookedUpEntry, exit
                                [EntryFactory] EntryFactoryImpl:wrapEntryForWriting, exit
                                [Interceptor] NonTxDistributionInterceptor:visitPutKeyValueCommand, entry
                                  [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                                  [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
                                  [Interceptor] CallInterceptor:visitPutKeyValueCommand, entry
                                    [Command] PutKeyValueCommand:perform, entry
                                      [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, entry
                                      [EntryLookup] SingleKeyNonTxInvocationContext:lookupEntry, exit
                                    [Command] PutKeyValueCommand:perform, exit
                                  [Interceptor] CallInterceptor:visitPutKeyValueCommand, exit
                                [Interceptor] NonTxDistributionInterceptor:visitPutKeyValueCommand, exit
                                [DataContainer] DefaultDataContainer:peek, entry
                                [DataContainer] DefaultDataContainer:peek, exit
                                [DataContainer] DefaultDataContainer:put, entry
                                [DataContainer] DefaultDataContainer:put, exit
                              [Interceptor] EntryWrappingInterceptor:visitPutKeyValueCommand, exit
                            [Interceptor] NonTransactionalLockingInterceptor:visitPutKeyValueCommand, exit
                          [Interceptor] StateTransferInterceptor:visitPutKeyValueCommand, exit
                        [Interceptor] CacheMgmtInterceptor:visitPutKeyValueCommand, exit
                      [Interceptor] InvocationContextInterceptor:visitPutKeyValueCommand, exit
                    [Interceptor] DistributionBulkInterceptor:visitPutKeyValueCommand, exit
                  [Command] SingleRpcCommand:perform, exit
                  [Marshaller] GlobalMarshaller:objectToBuffer, entry
                  [Marshaller] GlobalMarshaller:objectToBuffer, exit
                  [Marshaller] GlobalMarshaller:objectFromByteBuffer, entry
                  [Marshaller] GlobalMarshaller:objectFromByteBuffer, exit
                [RpcManager] RpcManagerImpl:invokeRemotely, exit
              [Interceptor] NonTxDistributionInterceptor:visitPutKeyValueCommand, exit
              [DataContainer] DefaultDataContainer:peek, entry
              [DataContainer] DefaultDataContainer:peek, exit
              [DataContainer] DefaultDataContainer:put, entry
              [DataContainer] DefaultDataContainer:put, exit
            [Interceptor] EntryWrappingInterceptor:visitPutKeyValueCommand, exit
          [Interceptor] NonTransactionalLockingInterceptor:visitPutKeyValueCommand, exit
       [Interceptor] StateTransferInterceptor:visitPutKeyValueCommand, exit
    [Interceptor] CacheMgmtInterceptor:visitPutKeyValueCommand, exit
  [Interceptor] InvocationContextInterceptor:visitPutKeyValueCommand, exit
[Interceptor] DistributionBulkInterceptor:visitPutKeyValueCommand, exit
===== UPDATE KEY = key2 END =====

更新時も、登録時とそう変わりませんね。

Primaryかどうかで、けっこう変わるものなんですねぇ…。

いったんここまで

ここらで長さが限界のようなので、続きは次の記事へ。
InfinispanのDistributed Cacheのput／getをトレースする（Local NodeがOnwerではない場合） - CLOVER

今回作成したコードは、こちらに置いています。
https://github.com/kazuhira-r/infinispan-getting-started/tree/master/embedded-trace-distributed-putget