Monday, February 21, 2011

memcachedのstats slabsを解析するRubyスクリプト

memcachedのstats slabsの項目名は直感的でない。

例えば、
free_chunksは、delete等されて再利用可能なチャンク数
free_chunks_endが最後にアロケートされたページで一度もsetされていないチャンク数
とかは、memcachedのソースを読んでやっと意味がわかった。

また、チューニングの際に必要な、アラインメントによる無駄領域の合計がぱっと見でわからなかったりする。

とういことで、
memcachedのstats slabs統計情報を解析するRubyスクリプトを張り付けておく。

# テキストプロトコルにしか対応してません。
# バイナリプロトコル専用のmemachedへは、rubyのmemcachedライブラリを使うように改造すりゃできる。


起動オプション
Usage:
./better_stats_slabs.rb -d /path_to_dir
or ./better_stats_slabs.rb -f /path_to_file
or ./better_stats_slabs.rb -h localhost:11211,localhost11222

Byte表示  オプションなし(デフォルト)
KiloByte表示 -k
MegaByte表示 -m
GigaByte表示 -g

出力結果

出力説明

STAT1..の行はスラブクラスごとの情報、下のtotalは全体の情報。
数字は全部サイズ。(byte, kB, MB GBの切り替えはオプションで可能)

空き領域が0のスラブクラスの先頭にはアスタリスクを表示している。
どのスラブでout of memoryが発生しているか、が分かる。

never_usedは、free_chunks_endのサイズ合計であり、最後に割り当てられたスラブ(ページ)の空き領域
reusableは、free_chunksのサイズ合計であり、delete済みのチャンク数合計
free_totalは、never_usedと、reusableの合計。つまり、そのスラブの空き領域合計サイズ。
free_totalが0だと、次にそのスラブクラスにsetした際にmallocされるってこと。(-Lオプションつけない場合)

item_sizeは、アラインメントを意識したアイテムの平均サイズの合計
wastedは、アラインメントを意識したアイテムの平均無駄サイズの合計
item_size + wastedが使用中チャンクサイズの合計です。
チューニング時にgrowth_factorを決める際に参考にできる。

total mallocは、スラブ用領域に割り当てられたサイズの合計、
total free sizeは空き領域合計
total ued sizeは使用中チャンクサイズ合計
items sizeの割合は、スラブ用メモリ領域全体のうちのアイテム本体のサイズが占める割合
wasted sizeの割合は、スラブ用メモリ領域全体のうちの無駄領域のサイズが占める割合


ソース
#!/usr/bin/ruby
# encoding: UTF-8

def comma(number)
  number.to_s.reverse.gsub(/(\d{3})(?=\d)/, '\1,').reverse
end

def percent(numerator, denominator)
  (denominator == 0 ? "- " : (100 * numerator / denominator).to_s).rjust(3)
end

alias :org_printf :printf
def printf(fmt, *args)
  org_printf(fmt, *args.map{|a| a.is_a?(Numeric) ? a / $options[:unit_scale] : a})
end

def stats_slabs(host_port)
  host, port = host_port.split(":").first, host_port.split(":").last
  lines = []
  begin
    TCPSocket.open(host, port) do |s|
      s.puts "stats slabs"
      while "END" != (line = s.gets.chop)
        lines << line
      end
    end
  rescue => e
    puts "counld not connect to #{host_port}"
    puts e.message
  end
  lines
end

def parse(lines)
  chunks_stats = []
  lines.each do |line|
    case line
      when /^STAT (\d+).*:chunk_size (\d+)/
        chunks_stats << {no: $1, size: $2.to_i,
          previous_size: chunks_stats.last ? chunks_stats.last[:size].to_i : 0 }
      when /^STAT.*:total_chunks (\d+)/
        chunks_stats.last[:total_chunks] = $1.to_i
      when /^STAT.*:used_chunks (\d+)/
        chunks_stats.last[:used_chunks] = $1.to_i
      when /^STAT.*:free_chunks_end (\d+)/
        chunks_stats.last[:free_chunks_end] = $1.to_i
      when /^STAT.*:free_chunks (\d+)/
        chunks_stats.last[:free_chunks] = $1.to_i
    end
  end
  chunks_stats
end

def calc_and_print(chunks_stats)

  total_malloced = 0 # total size of all chunks.

  total_free_size = 0 # total size of free chunks.
  total_used_size = 0 # total size of used chunks.

  total_items_size_about = 0 # total size of items.
  total_waste_size_about = 0 # total size of wasted spaces by align.

  puts "(unit: #{$options[:unit]})"
  chunks_stats.each_with_index do |stat, i|

    total_malloced += (stat[:size] * stat[:total_chunks])

    # The number of free chunks in a subclass = free_chunks_end + free_chunks
    sum_unused_size = stat[:size] * (stat[:free_chunks_end])   # chunks has not used yet.
    sum_reusable_size = stat[:size] * (stat[:free_chunks])     # deleted chunks.
    sum_free_size = sum_unused_size + sum_reusable_size
    total_free_size += sum_free_size

    used_size = stat[:size] * stat[:used_chunks]
    total_used_size += used_size

    # The average of wasted size(unused space) of a chunk.
    agv_wasted_size_per_chunk = (stat[:size] - stat[:previous_size] ) / 2

    sum_wasted_size = agv_wasted_size_per_chunk * stat[:used_chunks]
    total_waste_size_about += sum_wasted_size

    sum_items_size = (stat[:size] - agv_wasted_size_per_chunk) * stat[:used_chunks]
    total_items_size_about += sum_items_size

    printf(" #{sum_free_size == 0 ? "*" : " "} STAT %2d(#{stat[:size].to_s.rjust(4)}) | never_used: %10d reusable: %10d free_total: %10d | item_size : %10d (#{percent(sum_items_size, used_size)}%%) wasted: %10d (#{percent(sum_wasted_size, used_size)}%%)\n", stat[:no],  sum_unused_size, sum_reusable_size, sum_free_size, sum_items_size, sum_wasted_size)
  end

  puts ""
  printf(" total malloced  : %11d #{$options[:unit]}\n", total_malloced)
  printf(" total free size : %11d #{$options[:unit]}(#{percent(total_free_size, total_malloced)}%%)\n", total_free_size)
  printf(" total used size : %11d #{$options[:unit]}(#{percent(total_used_size, total_malloced)}%%)\n", total_used_size)
  printf("     items size ≈ %12d #{$options[:unit]}(#{percent(total_items_size_about, total_malloced)}%%)\n", total_items_size_about)
  printf("    wasted size ≈ %12d #{$options[:unit]}(#{percent(total_waste_size_about, total_malloced)}%%)\n", total_waste_size_about)
end

def parse_calc_print(header, lines)
  chunks_stats = parse(lines)
  puts "-" * 5 + header + "-" * 130
  return if chunks_stats.empty?
  calc_and_print chunks_stats
end

Usage = "Usage:
               ./better_stats_slabs.rb -d /path_to_dir
            or ./better_stats_slabs.rb -f /path_to_file
            or ./better_stats_slabs.rb -h localhost:11211,localhost11222

            Byte     ./better_stats_slabs.rb -d /path_to_dir
            KiloByte ./better_stats_slabs.rb -d /path_to_dir -k
            MegaByte ./better_stats_slabs.rb -d /path_to_dir -m
            GigaByte ./better_stats_slabs.rb -d /path_to_dir -g
        "
$options = {unit: "Byte", unit_scale: 1}
require 'optparse'
OptionParser.new{|opt|
  Version = "0.1"
  opt.banner = Usage
  opt.on("-k", "kB", "KilloByte") do
    $options[:unit] = "kB"
    $options[:unit_scale] = 1024
  end
  opt.on("-m", "MB", "MegaByte") do
    $options[:unit] = "MB"
    $options[:unit_scale] = 1024 ** 2
  end
  opt.on("-g", "GB", "GigaByte") do
    $options[:unit] = "GB"
    $options[:unit_scale] = 1024 ** 3
  end
  opt.on("-f filepath", "a file which had saved 'stats slabs'.") do |file|
    $options[:file] = file
  end
  opt.on("-d dir_path", "a dir path wihch has 'stats slabs' files.") do |dir|
    $options[:dir] = dir
  end
  opt.on("-h localhost:11211,localhost11222", "Host:Port of memcached process. ex. localhost:11211,localhost:11212") do |hs|
    $options[:hosts_and_ports] = hs
  end
  opt.parse!(ARGV)
}

if file = $options[:file]
    lines = File.readlines(File.expand_path file)
    parse_calc_print(file, lines)
elsif dir = $options[:dir]
    Dir.glob("#{dir}/*") do |path|
      lines= File.readlines(File.expand_path path)
      parse_calc_print(path, lines)
    end
elsif hs = $options[:hosts_and_ports]
    require 'socket'
    host_port_array = hs.split(",").map{|h| h.strip}
    host_port_array.each do |h|
      lines = stats_slabs(h)
      parse_calc_print(h, lines)
    end
else
  puts Usage
end

Thursday, February 17, 2011

動作中のmemcachedのログ出力レベルをGDBで無理やり変更する方法

memcached起動オプションで、-vvvをつけると標準エラー出力にログが表示される。
(-vvvオプションの詳細は、こことか詳しい。)

デバッグ目的で、起動中memcachedプロセスのログレベルをコマンドで変更したかったのだけど、動的にログレベルを変更するコマンドが見当たらない。

コマンドで用意されてなけりゃ、GDBで。
ということで、GDBでmemcachedプロセスにアタッチしてログ出力モード用の変数を無理やり変更したらできました(笑)

以下、手順を書いときます。


memcachedを-vつけずに起動(デバッグログ非表示モード)
kanbe@kanbe-laptop% ./memcached -p 11211 -r -B auto -C -m 10 -M -f 1.25 -I 1000000 -t 24 -c 256 -R 20

この状態で、telnetから適当にsetする。
memcachedプロセスの標準エラー出力には何も表示されない。


GDBでアタッチ

デバッグレベル用変数は、settings.verbose

verbose levelを最強にしてみる。(memcached起動オプションの-vvvと同じ)

(gdb) whatis settings
type = struct settings
(gdb) ptype settings
type = struct settings {
  size_t maxbytes;
  int maxconns;
  int port;
  int udpport;
  char *inter;
  int verbose;
  rel_time_t oldest_live;
  int evict_to_free;
  char *socketpath;
  int access;
  double factor;
  int chunk_size;
  int num_threads;
  char prefix_delimiter;
  int detail_enabled;
  int reqs_per_event;
  _Bool use_cas;
  enum protocol binding_protocol;
  int backlog;
  int item_size_max;
  _Bool sasl;
}
(gdb) p settings.verbose
$3 = 0
(gdb) set write on
(gdb) set settings.verbose = 3
(gdb) p settings.verbose
$4 = 3
(gdb) c
Continuing.

この状態でもう一回telnetからsetする
set ddddddddddddddddd 0 0 1
a
STORED

memcachedの標準エラー出力に以下が表示される
159: going from conn_read to conn_parse_cmd
<159 set ddddddddddddddddd 0 0 1 159: going from conn_parse_cmd to conn_nread > NOT FOUND ddddddddddddddddd
>159 STORED
159: going from conn_nread to conn_write
159: going from conn_write to conn_new_cmd
159: going from conn_new_cmd to conn_waiting
159: going from conn_waiting to conn_read

動いてるmemcachedプロセスのログレベルを変更できた!


参考

プログラムへのパッチ適用

実行中のmemcachedプロセスをGDBでdebugする方法

アタッチするプロセス番号を取得
kanbe@kanbe-laptop% ps -aux |grep memcached
kanbe 26951 0.2 0.0 622312 1376 pts/1 Sl+ 11:34 0:00 ./memcached -vvv -p 11211 -r -B auto -C -m 10 -M -f 1.25 -I 1000000 -t 24 -c 256 -R 20 -L

process番号は26951

アタッチしてブレイクポイントをセット
cd /path/to/memcached_install_dir/bin
sudo gdb memcached
(gdb) attach 26951
(gdb) b slabs_alloc
(gdb) c
Continuing.
別端末からtelnetで適当にset
kanbe@kanbe-laptop% telnet localhost 11211
Trying 127.0.0.1...
Connected to localhost.localdomain.
Escape character is '^]'.
set key 1 0 0 1
gdb上で該当threadに切り替わり、セットしたブレイクポイントのとこで止まる
[Switching to Thread 0x7f9b5adbd700 (LWP 26952)]
Breakpoint 1, slabs_alloc (size=60, id=1) at slabs.c:421
421 void *slabs_alloc(size_t size, unsigned int id) {

あとは、煮るなり焼くなり。

デタッチ
(gdb) detach
Detaching from program: /home/kanbe/work/memcached/bin/memcached, process 26951
!!!!!!!!!! 注意点 !!!!!!!!

attachした状態でrun, quitすると、memcachedプロセスが止まってしまう!!
(一応ほんとにプロセス止めるの?っていう確認メッセージが出る)

gdbを終了するときはdetachしてからquitで。

以下、既に実行中のプロセスのデバッグより引用

detach
アタッチされたプロセスのデバッグが終了した場合には、 detachコマンドを使用してそのプロセスをGDBの管理から解放することができます。 プロセスからディタッチしても、 そのプロセスは実行を継続します。 detachコマンド実行後は、 ディタッチされたプロセスと GDBは互いに完全に依存関係がなくなり、 attachコマンドによる別のプロセスへのアタッチや、 runコマンドによる別のプロセスの起動が可能になります。 detachコマンドを実行後RETキーを押しても、 detachコマンドは再実行されません。

プロセスがアタッチされている状態で、 GDBを終了したりrunコマンドを使用したりすると、 アタッチされたプロセスを終了させてしまいます。 デフォルトの状態では、 このようなことを実行しようとすると、 GDBが確認を求めてきます。 この確認処理を行うか否かは、 set confirmコマンドで制御可能です (オプションの警告およびメッセージ参照)。

参考ページ

Debugging with GDB

Friday, February 11, 2011

python: Listから重複を無くす

>>> L = [1, 2, 1, 3, 2, 4, 5]
>>> set(L)
{1, 2, 3, 4, 5}
>>> L = list(set(L)) # Remove duplicates
>>> L
[1, 2, 3, 4, 5]

Lerning Python 4th P138

Wednesday, December 22, 2010

Rails3で動的にログレベルを変更する

Rails3で大量データをBulkInsertで、大量データをActiveRecord経由でInsertしまくったんだけどさ、log/devlelopment.logみたらなんだかこんなwarningが大量に吐かれてるんですよ。

WARNING: Can't mass-assign protected attributes: column_id

importした行数分。

こりゃいかんということでちょっと調べたけど、わがらながったのでさ、
めんどくせぇからImportの時だけ一時的にログレベルを変更するという外道的解決をした時のメモ。

Rails.logger.levelを変えたらできました。

Rails.logger.level = 0 ... debug
Rails.logger.level = 3 ... error
ほかは調べてないけど、ログファイル見ながらlevelをかえれば分かるはず。

Rails3で大量データをBulkInsert

import元のOracleからActiveRecord経由で大量データをimportするときに
Model.create とかModel.new -> Model.saveだとSQLがマシンガンのようにながれまくるので、いつまで待っても終わらない。

そりゃ、SQL一発でバルクインサートでしょうってことで、このへんをみながらやってみた。
activerecord-import
Bulk insertion of data with ActiveRecord

log/development.logを見ながら確認したんだけど、
SQLiteだとバルクインサート的に書いても、SQLが連発される。
MySQLにしたらInsert文が1発のみだった。

Saturday, November 13, 2010

S25

S-99: Ninety-Nine Scala Problemsを試してみる。
勉強のためにListのAPIはなるべく使わない方向。

// P25 (*) Generate a random permutation of the elements of a list.
// Hint: Use the solution of problem P23.
// Example:
// scala> randomPermute(List('a, 'b, 'c, 'd, 'e, 'f))
// res0: List[Symbol] = List('b, 'a, 'd, 'c, 'e, 'f)

// P20 (*) Remove the Kth element from a list.
def removeAt[T](i: Int, xs: List[T]) = {
  def r(i: Int, xs: List[T], acc: List[T]): (List[T], T) = (i, xs) match {
    case (0, h :: t) => (acc.reverse ::: t, h)
    case (i, h :: t) => r(i - 1, t, h :: acc)
  }
  if(i < 0 || xs.size <= i) throw new NoSuchElementException else r(i, xs, Nil)
}

import scala.util.Random
def randomPermute[T](xs: List[T]) = {
  val rand = new Random
  def r(ys: List[T], acc: List[T]): List[T] = {
    if(ys.size == 1) ys.head :: acc
    else {
      val (rest, removed) = removeAt(rand.nextInt(ys.size), ys)
      r(rest, removed :: acc)
    }
  }
  if(xs.isEmpty) Nil else r(xs, Nil)
}
解答例
またもや、してやられたぜ!