特定の Path/Link の Latency を計測する

はじめに

NW 内の特定の Path/Link の Latency を計測する方法を試してみたので紹介。
やり方を教えてくれた Huawei さんありがとうございます。

構成

まず NW を用意します。IP CLOS のよくある構成を GNS3 の上に SW 代わりの Juniper vMX 16.2R1.6 で組みました。
vQFX を使えれば良かったんですが、自分の環境では安定して動かないので仕方なく vMX で代用です。
PtoP は 192.168.0.0/16 系の /31 で組んで、BGP で Loopback である 172.16.0.X 系のアドレスを広告。
GTracer とあるのが計測用の CentOS7 ノードで、leaf00 が 10.10.10.0/24 経路を配信しています。

下準備

まず下準備として各 SW/RT と計測用ノードの間で GRE Tunnel を張ります。
といっても計測用パケットを GRE Tunnel に流す訳ではないので、SW/RT 側だけで計測用ノード側に設定は不要です。

e.g. on spine00

set chassis fpc 0 pic 0 tunnel-services
set interfaces gr-0/0/0 unit 0 tunnel source 172.16.0.3
set interfaces gr-0/0/0 unit 0 tunnel destination 10.10.10.1
set interfaces gr-0/0/0 unit 0 family inet address 172.16.200.3/24 # 設定しないと gr I/F が有効にならないので適当に付ける

計測手法

では spine00 => leaf01 の Path/Link の Latency を計測したいと思います。

計測用ノードから leaf01 へ行って戻ってくる Path は [GTracer => leaf00 => spine00 => leaf01 => spine00 => leaf00] になるので、hop 分の GRE Header を重ねたパケットを用意します。

各 SW/RT には GTracer (10.10.10.1) との GRE Tunnel が設定されているので、上記のパケットを受け取った SW/RT は先頭の GRE Header を剥がして、内側のパケットをそのまま転送します。
なので GRE Header を hop 分重ねることで任意の NW 内の Path/Link を指定してパケットを流すことができます。

そして特定 Path/Link の Latency は以下の 3 パターンの計測結果から求めます。

• t0 : 全て優先 Queue で任意の Path/Link を通るパターン
  

• t1 : 計測対象 Path/Link のみ非優先 Queue (User Traffic Queue)で通り、他を全て優先 Queue で通るパターン
  

• t2 : 計測対象 Path/Link を優先 Queue で往復、最後に非優先 Queue で通り、他を全て優先 Queue で通るパターン
  

上記を計測、以下の式に当てはめる事で特定の Path/Link の片方向の Latency、この場合だと spine00 => leaf01 の方向の Latency が求められるそうです。

((t1 + t2) / 2) - t0

計測

理屈は分かったので、試しに計測してみましょう。
とりあえず Path を渡すとかかった時間を測定してくれる物を用意しました。packetgen の gem に依存しているので、gem install packetgen してからどうぞ。

gtrace.rb

module GTrace
  require 'packetgen'
  require 'socket'
  require 'time'
  require 'timeout'
  
  DSCP_NC = 0xE0
  DSCP_BE = 0x00
  UDP_PORT = 64_444
  SRC_PORT = 64_444
  TIMEOUT = 3
  
  class GREHeader < PacketGen::Header::Base
    IP_PROTOCOL = 47
    define_field :csum_ver, PacketGen::Types::Int16
    define_field :ptype, PacketGen::Types::Int16
  end
  
  PacketGen::Header.add_class GREHeader
  PacketGen::Header::IP.bind_header GREHeader, protocol: GREHeader::IP_PROTOCOL
  GREHeader.bind_header PacketGen::Header::IP, ptype: 0x0800

  class GTrace
    def initialize(s_addr, f_addr)
      @s_addr = s_addr
      @f_addr = f_addr
    end
  
    def create_tracer(path)
      base_pkts = []
      path.each do |dst|
        base_pkts.push PacketGen.gen('IP', src: @s_addr, dst: dst.first, tos: dst.last, flag_df: true)
                                .add('GREHeader', csum_ver: 0, ptype: 0x0800)
      end
      base_pkts.push PacketGen.gen('IP', src: @f_addr, dst: @s_addr, tos: DSCP_NC, flag_df: true)
                              .add('UDP', sport: SRC_PORT, dport: UDP_PORT, body: (Time.now.to_f * 1000000).round)
      recalculate_checksum base_pkts
    end
  
    def recalculate_checksum(base_packets)
      psize = 0
      packets = []
      while base = base_packets.pop
        bsize = base.to_s.size
        base.ip.length = bsize + psize
        base.ip.calc_checksum
        packets.unshift base
        psize += bsize
      end
      packets
    end
  
    def send_packet(packet)
      ssock = Socket.new Socket::AF_INET, Socket::SOCK_RAW, Socket::IPPROTO_RAW
      sockaddr = Socket.sockaddr_in SRC_PORT, packet.first.ip.dst
      ssock.send packet.map(&:to_s).join, 0, sockaddr
      ssock.close
    end
  
    def measure_latency(path)
      rsocket = UDPSocket.open
      rsocket.bind '0.0.0.0', UDP_PORT
      pkt = create_tracer path
      ptime = (Time.now.to_f * 1000000).round
      Timeout.timeout(TIMEOUT) do
        send_packet pkt
        dtime, raddr = rsocket.recv(65_535)
        current = (Time.now.to_f * 1000000).round
        return (current - dtime.to_i) - (current - ptime)
        # adjusting to decrease the process time between create the packet and to sent it.
      end
    rescue Timeout::Error
      return false
    ensure
      rsocket.close
    end
  
    def calculate_path_latency(t0, t1, t2)
      t0_time = measure_latency t0
      t1_time = measure_latency t1
      t2_time = measure_latency t2
      if [t0_time, t1_time, t2_time].include? false
        puts 'Failed to measure the path latency due to some packets loss occurred.'
        return false
      end
      [t0_time, t1_time, t2_time, (((t1_time + t2_time) / 2) - t0_time)]
    end
  end
end

ちょっと格好悪いですが、Path を渡して計測します。
とりあえず比較のため spine00 => leaf01 と、spine01 => leaf01 の 2 区間を対象にしています。

main.rb

require './gtrace'
include GTrace

# Main
self_addr = '10.10.10.1'
from_addr = '10.10.10.10' # self と同じだとちゃんと受け取れなかったので適当に
gtrace = GTrace::GTrace.new self_addr, from_addr

puts 'the formula: ((t1_time + t2_time) / 2) - t0_time'
10.times do
t0_path = [['172.16.0.5', DSCP_NC], ['172.16.0.3', DSCP_NC], ['172.16.0.6', DSCP_NC], ['172.16.0.3', DSCP_NC], ['172.16.0.5', DSCP_NC]]
t1_path = [['172.16.0.5', DSCP_NC], ['172.16.0.3', DSCP_NC], ['172.16.0.6', DSCP_BE], ['172.16.0.3', DSCP_NC], ['172.16.0.5', DSCP_NC]]
t2_path = [['172.16.0.5', DSCP_NC], ['172.16.0.3', DSCP_NC], ['172.16.0.6', DSCP_NC], ['172.16.0.3', DSCP_NC], ['172.16.0.6', DSCP_NC], ['172.16.0.3', DSCP_BE], ['172.16.0.5', DSCP_NC]]
t0, t1, t2, c = gtrace.calculate_path_latency(t0_path, t1_path, t2_path)
puts "Path: spine00 to leaf01: ((#{"% 5d" % t1} +#{"% 5d" % t2}) / 2) - #{"% 5d" % t0} = #{"% 4d" % c} micro seconds" if t0
end
puts ''
10.times do
t0_path = [['172.16.0.5', DSCP_NC], ['172.16.0.3', DSCP_NC], ['172.16.0.6', DSCP_NC], ['172.16.0.4', DSCP_NC], ['172.16.0.6', DSCP_NC], ['172.16.0.3', DSCP_NC], ['172.16.0.5', DSCP_NC]]
t1_path = [['172.16.0.5', DSCP_NC], ['172.16.0.3', DSCP_NC], ['172.16.0.6', DSCP_NC], ['172.16.0.4', DSCP_NC], ['172.16.0.6', DSCP_BE], ['172.16.0.3', DSCP_NC], ['172.16.0.5', DSCP_NC]]
t2_path = [['172.16.0.5', DSCP_NC], ['172.16.0.3', DSCP_NC], ['172.16.0.6', DSCP_NC], ['172.16.0.4', DSCP_NC], ['172.16.0.6', DSCP_NC], ['172.16.0.4', DSCP_NC], ['172.16.0.6', DSCP_NC], ['172.16.0.4', DSCP_NC], ['172.16.0.6', DSCP_BE], ['172.16.0.3', DSCP_NC], ['172.16.0.5', DSCP_NC]]

t0, t1, t2, c = gtrace.calculate_path_latency(t0_path, t1_path, t2_path)
puts "Path: spine01 to leaf01: ((#{"% 5d" % t1} +#{"% 5d" % t2}) / 2) - #{"% 5d" % t0} = #{"% 4d" % c} micro seconds" if t0
end

では計測してみましょう。

[root@grepc]# ruby main.rb 
the formula: ((t1_time + t2_time) / 2) - t0_time
Path: spine00 to leaf01: ((  315 +  353) / 2) -   407 =  -73 micro seconds
Path: spine00 to leaf01: ((  345 +  509) / 2) -   341 =   86 micro seconds
Path: spine00 to leaf01: ((  273 +  519) / 2) -   281 =  115 micro seconds
Path: spine00 to leaf01: ((  488 +  667) / 2) -   443 =  134 micro seconds
Path: spine00 to leaf01: ((  342 +  355) / 2) -   281 =   67 micro seconds
Path: spine00 to leaf01: ((  280 +  429) / 2) -   398 =  -44 micro seconds
Path: spine00 to leaf01: ((  420 +  366) / 2) -   453 =  -60 micro seconds
Path: spine00 to leaf01: ((  571 +  357) / 2) -   509 =  -45 micro seconds
Path: spine00 to leaf01: ((  279 +  354) / 2) -   308 =    8 micro seconds
Path: spine00 to leaf01: ((  443 +  612) / 2) -   545 =  -18 micro seconds

Path: spine01 to leaf01: ((  391 + 1034) / 2) -   643 =   69 micro seconds
Path: spine01 to leaf01: ((  408 +  534) / 2) -   427 =   44 micro seconds
Path: spine01 to leaf01: ((  358 +  550) / 2) -   376 =   78 micro seconds
Path: spine01 to leaf01: ((  362 +  594) / 2) -   594 = -116 micro seconds
Path: spine01 to leaf01: ((  361 +  644) / 2) -   382 =  120 micro seconds
Path: spine01 to leaf01: ((  682 + 1184) / 2) -   686 =  247 micro seconds
Path: spine01 to leaf01: ((  759 + 1079) / 2) -   739 =  180 micro seconds
Path: spine01 to leaf01: ((  449 +  597) / 2) -   490 =   33 micro seconds
Path: spine01 to leaf01: ((  680 + 1065) / 2) -   430 =  442 micro seconds
Path: spine01 to leaf01: ((  694 +  941) / 2) -   735 =   82 micro seconds

、、、イマイチ安定していないですね。VM 環境だからでしょうか。
輻輳が起きた時にちゃんと Latency が悪化するか確認するため、spine00 => leaf01 間に 1Mbps の shaping 設定をして適当なトラフィックで埋めてから計測します。

参考: Example: Configuring Hierarchical CoS on vMX

[root@grepc pkgen]# ruby main.rb 
the formula: ((t1_time + t2_time) / 2) - t0_time
Path: spine00 to leaf01: ((  294 +  370) / 2) -   372 =  -40 micro seconds
Path: spine00 to leaf01: ((  664 +  623) / 2) -   594 =   49 micro seconds
Path: spine00 to leaf01: ((  506 +  666) / 2) -   537 =   49 micro seconds
Path: spine00 to leaf01: ((  585 +  628) / 2) -   512 =   94 micro seconds
Path: spine00 to leaf01: ((  488 +  661) / 2) -   473 =  101 micro seconds
Failed to measure the path latency due to some packets loss occurred.
Path: spine00 to leaf01: ((  490 +  609) / 2) -   590 =  -41 micro seconds
Path: spine00 to leaf01: ((  718 +  794) / 2) -   481 =  275 micro seconds
Path: spine00 to leaf01: ((  779 +  784) / 2) -   362 =  419 micro seconds
Path: spine00 to leaf01: ((  531 +  644) / 2) -   642 =  -55 micro seconds

Path: spine01 to leaf01: ((  765 + 1190) / 2) -   681 =  296 micro seconds
Path: spine01 to leaf01: ((  412 +  921) / 2) -   501 =  165 micro seconds
Path: spine01 to leaf01: ((  409 +  588) / 2) -   430 =   68 micro seconds
Path: spine01 to leaf01: ((  605 +  962) / 2) -   852 =  -69 micro seconds
Path: spine01 to leaf01: ((  711 +  884) / 2) -   619 =  178 micro seconds
Path: spine01 to leaf01: ((  599 +  965) / 2) -   615 =  167 micro seconds
Path: spine01 to leaf01: ((  359 + 1344) / 2) -   854 =   -3 micro seconds
Path: spine01 to leaf01: ((  483 +  946) / 2) -   367 =  347 micro seconds
Path: spine01 to leaf01: ((  366 +  532) / 2) -   395 =   54 micro seconds
Path: spine01 to leaf01: ((  438 +  648) / 2) -   812 = -269 micro seconds

、、、駄目ですね。
期待した結果は spine00 => leaf01 間の Latency は悪化するが、spine01 => leaf01 間は変化しない、という物だったのですが、期待外れです。

まとめ

GRE Tunnel の設定ができる SW/RT であれば、メーカー問わず測定対象にすることができるのがいいですね。
L2 CLOS だとか LAG の分散には対応できませんが、IP CLOS や Backbone NW はいけるかな。
VM 環境だと micro は誤差なのか期待した結果は得られませんでしたが、コードの誤りな気もするので物理環境でのテストも含めてもうちょっとやってみたいと思います。

継続的に監視するなら daemon 化とか Path の ID/Sequence Number を計測パケットに埋め込むのと、ちゃんとグラフ化する UI が必要かな、、
Path の作成や管理も手間なので、経路情報とか LLDP から自動生成するような物も欲しくなりますね。

尚、ちゃんとした製品は Huawei さんが Fabric Insight という名前で販売されるそうです。
UI 含めて開発するのは大変だから、正直製品を買う方がイイヨネ

さいごに

面白いお話しをありがとうございました Huawei さん
内容に誤りがあったらごめんなさい、、