diff --git a/.gitignore b/.gitignore index d66d87e..f7f0131 100644 --- a/.gitignore +++ b/.gitignore @@ -4,6 +4,7 @@ # Compiled Dynamic libraries *.so +*.dylib # Compiled Static libraries *.la diff --git a/COVERAGE.md b/COVERAGE.md new file mode 100644 index 0000000..e8f6dc9 --- /dev/null +++ b/COVERAGE.md @@ -0,0 +1,22 @@ +# Twemcache Test Coverage + +To generate test coverage using gcov & lcov. + +## Requirement +Have both gcov and lcov installed. + +## Build + +Configure Twemcache with no optimization and with gcov enabled +```sh + CFLAGS="-ggdb3 -O0" ./configure --enable-debug=full --enable-gcov +``` + +## Collect data (running at project root level) +```sh + lcov -c --no-external --rc lcov_branch_coverage=1 -i -b src/ -d src/ -o twemcache_base.info + make test + lcov -c --no-external --rc lcov_branch_coverage=1 -b src/ -d src/ -o twemcache_test.info + lcov -a twemcache_base.info -a twemcache_test.info --rc lcov_branch_coverage=1 -o twemcache_total.info + genhtml --ignore-errors source twemcache_total.info --legend --output-directory=/tmp/twemcache +``` diff --git a/ChangeLog b/ChangeLog index 0b641f6..28206de 100644 --- a/ChangeLog +++ b/ChangeLog @@ -1,3 +1,17 @@ +2015-09-01 Cache Team + * twemcache: version 2.6.2 release + * Feature: adding "config maxbytes" command to adjust heap + * Feature: adding socket, memory, and context switch related stats + * Feature: adding max reporting for all gauges + * Fix: port signal handler patch from twemproxy + * Fix: update item_expire for flushed items + * Fix: updating settings.verbose when verbosity level changes + * Fix: adding long option form of -e + * Misc: changing default number of workers from 4 to 2 + * Misc: downsizing default connection buffer + * Misc: lower ac requirements; making -rdynamic linux only + * Misc: added coverage support; COVERAGE.md for instructions + 2013-06-04 Cache Team * twemcache: version 2.6.0 release * Fix: memory leak in suffix, with contribution from @ferlatum & @skuzmich diff --git a/README.md b/README.md index af01d24..0184207 100644 --- a/README.md +++ b/README.md @@ -104,7 +104,7 @@ Eviction is triggered when a cache reaches full memory capacity. This happens wh * Slab LRA eviction (4) - choose the least recently accessed slab, and evict all items from it to reuse the slab. * Slab LRC eviction (8) - choose the least recently created slab, and evict all items from it to reuse the slab. Eviction ignores freeq & lruq to make sure the eviction follows the timestamp closely. Recommended if cache is updated on the write path. -Eviction strategies can be *stacked*, in the order of higher to lower bit. For example, `-M 5` means that if slab LRU eviciton fails, Twemcache will try item LRU eviction. +Eviction strategies can be *stacked*, in the order of higher to lower bit. For example, `-M 5` means that if slab LRA eviciton fails, Twemcache will try item LRU eviction. ## Observability diff --git a/configure.ac b/configure.ac index 8a40cdb..c930be6 100644 --- a/configure.ac +++ b/configure.ac @@ -1,11 +1,11 @@ # Define the package version numbers and the bug reporting address m4_define([MC_MAJOR], 2) m4_define([MC_MINOR], 6) -m4_define([MC_PATCH], 0) +m4_define([MC_PATCH], 2) m4_define([MC_BUGS], [cache-team@twitter.com]) # Initialize autoconf -AC_PREREQ([2.64]) +AC_PREREQ([2.63]) AC_INIT([twemcache], [MC_MAJOR.MC_MINOR.MC_PATCH], [MC_BUGS]) AC_CONFIG_SRCDIR([src/mc.c]) AC_CONFIG_AUX_DIR([config]) @@ -26,6 +26,15 @@ AC_DEFINE(MC_VERSION_STRING, "MC_MAJOR.MC_MINOR.MC_PATCH", [Define the version s # Checks for language AC_LANG([C]) +# Checks for OS and set OS variables +AC_CANONICAL_HOST +case $host_os in + linux*) OS_LINUX=yes ;; + darwin*) OS_DARWIN=yes ;; + *) AC_MSG_ERROR([Your platform is not currently supported]) ;; +esac +AM_CONDITIONAL([RDYNAMIC], [test x$OS_LINUX = xyes]) + # Checks for programs AC_PROG_CC AC_PROG_INSTALL @@ -142,7 +151,7 @@ AS_IF( trylibeventdir="" AC_ARG_WITH([libevent], [AS_HELP_STRING([--with-libevent=@<:@path@:>@], [specify path to libevent install])], - [trylibeventdir=$withval], [] + [trylibeventdir=$withval], [trylibeventdir=] ) LIBEVENT_URL=http://libevent.org AC_CACHE_CHECK([for libevent directory], [ac_cv_libevent_dir], @@ -250,6 +259,28 @@ AS_CASE([x$enable_static], [AC_MSG_FAILURE([invalid value ${enable_static} for --enable-static])]) AC_MSG_RESULT([$enable_static]) +AC_MSG_CHECKING([whether to enable test coverage]) +AC_ARG_ENABLE([gcov], + [AS_HELP_STRING( + [--enable-gcov], + [enable coverage testing with gcov]), + ], + [], + [enable_gcov=no]) +AS_CASE([x$enable_gcov], + [xyes], [ + AC_DEFINE([HAVE_GCOV], [1], [Define to 1 if gcov is enabled]) + GCOV_CFLAGS="-O0 -fprofile-arcs -ftest-coverage" + GCOV_LDFLAGS="-lgcov" + ], + [xno], [ + GCOV_CFLAGS="" + GCOV_LDFLAGS="" + ]) +AC_MSG_RESULT([$enable_gcov]) +AC_SUBST(GCOV_CFLAGS) +AC_SUBST(GCOV_LDFLAGS) + # Define Makefiles AC_CONFIG_FILES([Makefile src/Makefile]) diff --git a/scripts/twctop26.rb b/scripts/twctop26.rb new file mode 100755 index 0000000..c1ee73d --- /dev/null +++ b/scripts/twctop26.rb @@ -0,0 +1,961 @@ +#!/usr/bin/env ruby + +require "optparse" +require "socket" +require "yaml" +require "benchmark" + +DELAY = 0.05 +NA = " -- " +SLAB_SIZE = 1024 * 1024 +EXPIRY = 14 * 24 * 60 * 60 + +# We have three views: slab, command and host +# host view should be the summary of the cache pool +# slab view tells the distribution of items among slab classes +# command view summarizes the mix, hit/miss/success rate of commands + +# FIXME: split slab view into two: slab-data view and slab-command view +# In the slab-command view we should use the bar to show stacked r/w/d requests + +SLAB_FIELDS = { # minimum width: 115 characters; 140+ to make the bar look good + :size => { :title => "SLAB", :width => 7, :justify => :left }, # item size b + :slab => { :title => "#SLAB", :width => 7 }, # number of slabs + :item => { :title => "ITEM", :width => 11 }, # absolute number of items + :item_pct => { :title => "ITEM(%)", :width => 11 }, # slab utilization + :data_pct => { :title => "KEYVAL(%)", :width => 11 }, # effective use of items + :payload_pct => { :title => "VALUE(%)", :width => 11 }, # value/(key+value) ratio + :expire => { :title => "REC(/s)", :width => 8 }, + :evict => { :title => "EVT(/s)", :width => 8 }, + :slab_evict => { :title => "SEVT(/s)", :width => 9 }, # slab eviction + :locate => { :title => "LOCATE(/s)", :width => 11 }, + :insert => { :title => "INSERT(/s)", :width => 11 }, + :bar => { :title => " ", :width => 0 }, # mem util/allocation bar +} + +HOST_FIELDS = { # minimum width: 140 characters, if this is too wide remove the REQ fields + :host => { :title => "INSTANCE", :width => 24, :justify => :left }, # ip:port + :uptime => { :title => "UPTIME", :width => 7 }, + :util => { :title => "UTIL(%)", :width => 10 }, # data / max memory allowed + :conn => { :title => "CONN", :width => 10 }, + :latency => { :title => "LATENCY", :width => 8 }, # rt time for "stats" + :expire => { :title => "EXPIRE(/s)", :width => 11}, + :evict => { :title => "EVICT(/s)", :width => 11 }, + :rdata => { :title => "BYTE_IN/s", :width => 11 }, + :wdata => { :title => "BYTE_OUT/s", :width => 11 }, + :req => { :title => "REQ(/s)", :width => 11 }, + :svrerr => { :title => "SVRERR(/s)", :width => 11 }, +} + +CMD_FIELDS = { # minimum width: 92 characters + :command => { :title => "COMMAND", :width => 8, :justify => :left }, + :rate => { :title => "REQUEST(/s)", :width => 12 }, + :success => { :title => "SUCCESS(%)", :width => 12}, + :hit => { :title => "HIT(%)", :width => 12 }, + :miss => { :title => "MISS(%)", :width => 12 }, + :exist => { :title => "EXISTS(%)", :width => 12 }, + :error => { :title => "CMDERR(/s)", :width => 12 }, + :mix => { :title => "MIX(%)", :width => 12 }, # % in total commands + # : => { :title => "(%)", :width => }, +} + +CMD = [ + :set, :cas, :add, :replace, :append, :prepend, :incr, :decr, # write + :get_key, :gets_key, # read + :delete, # delete +] +CMD_WRITE = [ + :set, :cas, :add, :replace, :append, :prepend, :incr, :decr, +] +CMD_READ = [ + :get_key, :gets_key, +] +CMD_SUCCESS = [ + :set, :cas, :add, :replace, :append, :prepend, +] +CMD_SUCCESS_GLOBAL = [ + :incr, :decr, +] +CMD_HITMISS = [ + :append, :prepend, :get_key, :gets_key, +] +CMD_HITMISS_GLOBAL = [ + :delete, :incr, :decr, +] +CMD_EXIST = [ + :cas, :add, +] + + +# change me to alter the displayed columns or their order +SLAB_ORDER = [ + :size, :slab, # slab basics + :item, :item_pct, :data_pct, :payload_pct, + # memory + :bar, # allocated memory + :expire, :evict, # item + :slab_evict, # slab + :locate, :insert, # command + ] +HOST_ORDER = [ + :host, # name + :uptime, # uptime + :util, :conn, # usage + :latency, # responsiveness + :expire, :evict, # churning + :rdata, :wdata, # throughput + :req, # command counts + :svrerr, # server errors + ] +CMD_ORDER = [ + :command, # name + :rate, # rate sent + :mix, # command mix + :success, :hit, # success update/locate + :miss, :exist, :error, # errors or failures + ] + +# display buffer +class ViewBuffer + attr_accessor :headers, :rows, :top_row + + def initialize + @headers = [] + @rows = [] + @top_row = 0 + end +end + +$buf = ViewBuffer.new +$winch = false + + +# format number/time to fit their column width +class Fixnum + def to_h + if self < 1.1 * 1024 + "%7d" % self + elsif self < 1.1 * 1024 ** 2 + "%6.1fK" % (self / 1024.0) + elsif self < 1.1 * 1024 ** 3 + "%6.1fM" % (self / (1024.0 ** 2)) + elsif self < 1.1 * 1024 ** 4 + "%6.1fG" % (self / (1024.0 ** 3)) + else + "%6.1fT" % (self / (1024.0 ** 4)) + end + end + + def to_time_string + if self <= 90 + "%4ds" % self + elsif self <= 90 * 60 + "%4dm" % (self / 60) + else + # 4 digits allow us to show an age of 9999 hrs/400 days, should be enough + # we decide not to go beyond hours coz age in days isn't very informative + "%4dh" % (self / 3600) + end + end +end + +class Float + def to_time_string + if self <= 0.0015 + "%4dus" % (self * 1_000_000).to_i + elsif self <= 1.5 + "%4dms" % (self * 1000).to_i + elsif self <= 90.0 + "%3dsec" % self + elsif self <= 90 * 60 + "%3dmin" % self + else + "%4dhr" % self + end + end +end + +class String + def text_size + self.gsub(/\033\[[\d;]*./, "").size + end + + def colorize(color) + if !$options[:raw] + "\033[#{color}m#{self}\033[39m" + else + self + end + end + + def red; self.colorize(31); end + def green; self.colorize(32); end + def blue; self.colorize(34); end + def cyan; self.colorize(36); end + def reverse; "\033[7m#{self}\033[27m"; end +end + +class ServerStats + attr_accessor :host, :slabs, :stats, :cmds + + def initialize(host) + @host = host + @slabs = {} # { chunk_size => { stat => value } } + @stats = {} # { stat => value } + @cmds = { + :count => {}, + :error => {}, + :success => {}, + :hit => {}, + :miss => {}, + :exist => {}, + } + name, port = host.split(":") + stats_data = {} + # global stats + timing + mc = TCPSocket.new(name, port) + elapsed = Benchmark.realtime do + mc.write("stats\r\n") + while (line = mc.gets) !~ /^END/ + if line =~ /^STAT (\S+) (\S+)/ + stats_data[$1] = $2 + end + end + end + stats_setting = {} + mc.write("stats settings\r\n") + while (line = mc.gets) !~ /^END/ + if line =~ /^STAT (\S+) (\S+)/ + stats_setting[$1] = $2 + end + end + + # slab stats + mc.write("stats slabs\r\n") + slab_data = [] + while (line = mc.gets) !~ /^END/ + if line =~ /^STAT (\d+):(\S+) (-?\d+)/ + while slab_data.size <= $1.to_i + slab_data << {} + end + slab_data[$1.to_i][$2] = $3.to_i + end + end + + # commands related metrics + CMD.each do |cmd| + @cmds[:count][cmd] = stats_data[cmd.id2name].to_i + @cmds[:error][cmd] = stats_data[cmd.id2name + "_error"].to_i + end + CMD_SUCCESS_GLOBAL.each do |cmd| + @cmds[:success][cmd] = stats_data[cmd.id2name + "_success"].to_i + end + CMD_SUCCESS.each do |cmd| + @cmds[:success][cmd] = stats_data[cmd.id2name + "_success"].to_i + end + CMD_HITMISS_GLOBAL.each do |cmd| + @cmds[:hit][cmd] = stats_data[cmd.id2name + "_hit"].to_i + @cmds[:miss][cmd] = stats_data[cmd.id2name + "_miss"].to_i + end + CMD_HITMISS.each do |cmd| + @cmds[:hit][cmd] = stats_data[cmd.id2name + "_hit"].to_i + @cmds[:miss][cmd] = stats_data[cmd.id2name + "_miss"].to_i + end + @cmds[:exist][:cas] = stats_data["cas_badval"].to_i + @cmds[:exist][:add] = stats_data["add_exist"].to_i + @cmds[:timestamp] = stats_data["aggregate_ts"].to_f + + @stats = { + :uptime => stats_data["uptime"].to_i, + :latency => elapsed, + :data => stats_data["data_curr"].to_i, + :maxbytes => stats_setting["maxbytes"].to_i, + :conn => stats_data["conn_curr"].to_i, + :req => CMD.inject(0) { |n, c| n += @cmds[:count][c] }, + :expire => stats_data["item_expire"].to_i, + :evict => stats_data["item_evict"].to_i, + :rdata => stats_data["data_read"].to_i, + :wdata => stats_data["data_written"].to_i, + :svrerr => stats_data["server_error"].to_i, + :timestamp => stats_data["aggregate_ts"].to_f, + } + slab_data.each do |d| + next if d.empty? + @slabs[d["chunk_size"]] = { + :data_curr => d["data_curr"], + :data_value => d["data_value_curr"], + :item_curr => d["item_curr"], + :slab_curr => d["slab_curr"], + :evict => d["item_evict"], + :slab_evict => d["slab_evict"], + :expire => d["item_expire"], + :locate => CMD_HITMISS.inject(0) { |n, c| n += d[c.id2name + "_hit"] }, + :insert => CMD_SUCCESS.inject(0) { |n, c| n += d[c.id2name + "_success"] }, + } if d["chunk_size"] + end + rescue => e + # ignore + end +end + +class SummaryStats + attr_accessor :slabs, :hosts, :cmds + + def initialize(host_stats_arr) + @slabs = {} # { chunk_size => { stat => value } } + @hosts = {} # { host => {stat => value} } + @cmds = { + :count => {}, + :error => {}, + :success => {}, + :hit => {}, + :miss => {}, + :exist => {}, + } + + @cmds[:timestamp] = 0.0 + host_stats_arr.each do |host_stats| + + # copy the per-host global metrics + @hosts[host_stats.host] = host_stats.stats + + # get per-slab metrics by sum up each across all hosts + host_stats.slabs.each do |chunk_size, slab_stats| + if @slabs[chunk_size] + slab_stats.each do |k, v| + @slabs[chunk_size][k] += v + end + else + slabs[chunk_size] = slab_stats + end + end + + # sum up command metrics across all hosts + CMD.each do |cmd| + for category in [:count, :error, :success, :hit, :miss, :exist] + if host_stats.cmds[category][cmd] + if @cmds[category][cmd] + @cmds[category][cmd] += host_stats.cmds[category][cmd] + else + @cmds[category][cmd] = host_stats.cmds[category][cmd] + end + end + end + end + @cmds[:timestamp] += host_stats.cmds[:timestamp] + end + #FIXME: getting timestamp this way doesn't really make sense + @cmds[:timestamp] /= @hosts.size + + # FIXME: Again, none of the follwing really makes sense + # NOTE: maybe we should also show the oldest besides average + @slabs.each do |chunk_size, slab| + slab[:timestamp] = Time.now.to_i + end + end +end + +module Screen + class << self + def cols + @cols + end + + def rows + @rows + end + + def with_ansi(&block) + yield unless $options[:raw] + end + + def display(&block) + @rows = 40 + @cols = 100 + # FFS THIS IS TERRIBLE + old_state = `stty -g` + get_screen_size + with_ansi { system "stty raw -echo" } + yield + ensure + system "stty #{old_state}" + end + + def get_screen_size + with_ansi do + terminfo = `stty -a` + if terminfo =~ /rows (\d+)/ + @rows = $1.to_i + end + if terminfo =~ /columns (\d+)/ + @cols = $1.to_i + end + end + end + + def cls + go(0, 0) + with_ansi do + STDERR.write("\033[0m\033[0J") + end + end + + def go(x, y) + x += @cols if x < 0 + y += @rows if y < 0 + with_ansi do + STDERR.write("\033[#{y};#{x}H") + end + end + + end +end + + +# ---------- + +Signal.trap("WINCH") do + $winch = true +end + +# change the string color if a metric flows over or under given threshold +def warning_string(value, warning_level, warning_style, format=nil) + # get the string + s = if format + format % value + else + value.to_time_string + end + + # decide the color + if (value >= 0 && # negative values were never updated + ((warning_style == :over && value > warning_level) || + (warning_style == :under && value < warning_level))) + s.red + else + s + end +end + +def display + if $winch + Screen.get_screen_size + $winch = false + end + + window_height = Screen.rows - $buf.headers.size - 1 + if $buf.top_row > $buf.rows.size - window_height + $buf.top_row = $buf.rows.size - window_height + end + if $buf.top_row < 0 + $buf.top_row = 0 + end + bottom_row = [ $buf.rows.size, $buf.top_row + window_height ].min + scrollbar = make_scrollbar(window_height, $buf.rows.size, $buf.top_row, bottom_row) + display_rows = $buf.rows.slice($buf.top_row, window_height) + unless $options[:raw] || (display_rows.size == $buf.rows.size) + display_rows = display_rows.zip(scrollbar).map do |r, s| + s + r[1..-1] + end + end + + Screen.cls + $buf.headers.each { |h| STDERR.write(h + "\r\n") } + display_rows.each { |row| STDERR.write(row + "\r\n") } + STDERR.write("\r\n") if $options[:raw] +end + +def show_help + Screen.cls + STDERR.print("\r\n") + STDERR.print("Commands:\r\n") + STDERR.print("\r\n") + STDERR.print(" H switch to hosts view\r\n") + STDERR.print(" S switch to slabs view\r\n") + STDERR.print(" C switch to command view\r\n") + STDERR.print("\r\n") + STDERR.print(" J scroll down\r\n") + STDERR.print(" K scroll up\r\n") + STDERR.print("\r\n") + STDERR.print(" Q quit (or ^C)\r\n") + STDERR.print("\r\n") + STDERR.print("Press any key to resume: ") + + while (STDIN.read(1) rescue "") == ""; end + display +end + +def check_key(seconds) + time_left = seconds + while time_left > 0 + c = STDIN.read_nonblock(1) rescue "" + # do something with c + if c == "\x03" || c == "q" || c == "Q" + exit + elsif c == "j" || c == "J" + $buf.top_row += 1 + display + elsif c == "k" || c == "K" + $buf.top_row -= 1 + display + elsif c == "s" || c == "S" + $state = "slab" + $buf.top_row = 0 + return + elsif c == "h" || c == "H" + $state = "host" + $buf.top_row = 0 + return + elsif c == "c" || c == "C" + $state = "command" + $buf.top_row = 0 + return + elsif c == "?" + show_help + end + display if $winch + sleep DELAY + time_left -= DELAY + end +end + +def make_scrollbar(scrollbar_height, total_size, view_top, view_bottom) + scrollbar_height -= 2 + return [] if scrollbar_height <= 0 || total_size <= 0 + top_extent = (view_top.to_f / total_size * scrollbar_height + 0.5).to_i + scrollbar_extent = (view_bottom.to_f / total_size * scrollbar_height + 0.5).to_i - top_extent + bottom_extent = scrollbar_height - top_extent - scrollbar_extent + rv = [] + rv << "^".cyan + top_extent.times { rv << " " } + scrollbar_extent.times { rv << " ".reverse.cyan } + bottom_extent.times { rv << " " } + rv << "v".cyan +end + +def ascii_bar(width, max, bar1, bar2) + bar1_extent = (bar1.to_f / max * width + 0.5).to_i + bar2_extent = (bar2.to_f / max * width + 0.5).to_i - bar1_extent + (width > 0) ? ("\#" * bar1_extent).red + ("-" * bar2_extent).green + " " * (width - bar1_extent - bar2_extent) : "" +end + +def build_headers(left_header, fields, field_definitions) + current_time = Time.now.strftime("%H:%M:%S") + $buf.headers = [] + padding = " " * [Screen.cols - current_time.text_size - left_header.text_size - 1, 0].max + $buf.headers << left_header + padding + current_time + field_widths = fields.inject(0) { |sum, field| sum + field_definitions[field][:width] } + # this only works if no more than one field is springy (width = 0) + field_definitions.each do |name, field_definition| + field_definition[:width] = Screen.cols - field_widths - 3 if field_definition[:width] == 0 + end + field_widths = fields.inject(0) { |sum, field| sum + field_definitions[field][:width] } + # left-justify the first field header + line = fields.inject("") do |line, field| + if (field_definitions[field][:justify] == :left) + line + field_definitions[field][:title].ljust(field_definitions[field][:width]) + else + line + field_definitions[field][:title].rjust(field_definitions[field][:width]) + end + end + $buf.headers << (line + " " * [Screen.cols - field_widths - 1, 0].max).reverse +end + +def build_row(row, fields, field_definitions) + fields.inject("") do |line, field| + if field_definitions[field][:justify] == :left + line + row[field].ljust(field_definitions[field][:width] + row[field].size - row[field].text_size) + else + line + row[field].rjust(field_definitions[field][:width] + row[field].size - row[field].text_size) + end + end +end + +def dump_slabs(slabs, last_slabs=nil) + slab_total = slabs.inject(0) { |n, (k, v)| n + v[:slab_curr] } + slot_total = slabs.inject(0) { |n, (k, v)| n + (SLAB_SIZE / k) * v[:slab_curr] } + slot_used = slabs.inject(0) { |n, (k, v)| n + v[:item_curr] } + byte_used = slabs.inject(0) { |n, (k, v)| n + k * v[:item_curr] } + usage = slot_used.to_f * 100 / slot_total + + slabs.each do |k, s| + s[:mem_total] = SLAB_SIZE * s[:slab_curr] + s[:mem_used] = k * s[:item_curr] + end + mem_max = slabs.map { |k, s| s[:mem_total] }.max + if mem_max.zero? + mem_max = 1 # to render the in slab view properly + end + + rates = {} + if last_slabs + slabs.each do |k, slab| + last_slab = last_slabs[k] + rate = {} + timespan_sec = slab[:timestamp] - last_slabs[k][:timestamp] + rate[:evict] = (slab[:evict] - last_slab[:evict]).to_f / timespan_sec + rate[:slab_evict] = (slab[:slab_evict] - last_slab[:slab_evict]).to_f / timespan_sec + rate[:expire] = (slab[:expire] - last_slab[:expire]).to_f / timespan_sec + rate[:locate] = (slab[:locate] - last_slab[:locate]).to_f / timespan_sec + rate[:insert] = (slab[:insert] - last_slab[:insert]).to_f / timespan_sec + rates[k] =rate + end + else + slabs.each do |k, slab| + rate = {} + rate[:evict] = slab[:evict] + rate[:slab_evict] = slab[:slab_evict] + rate[:expire] = slab[:expire] + rate[:locate] = slab[:locate] + rate[:insert] = slab[:insert] + rates[k] =rate + end + end + + left_header = " -SLAB VIEW- Total Slabs:#{slab_total.to_h}; Slot Used / Alloc: "\ + "#{slot_used.to_h} /#{slot_total.to_h} (#{"%3.1f" % usage}%)" + build_headers(left_header, SLAB_ORDER, SLAB_FIELDS) + + # build up data rows + $buf.rows = slabs.sort.map do |k, v| + rate = rates[k] + item_ratio = v[:slab_curr].nonzero? ? + v[:item_curr].to_f * 100 / (SLAB_SIZE / k * v[:slab_curr]) : 0 + data_ratio = v[:item_curr].nonzero? ? + v[:data_curr].to_f * 100 / (k * v[:item_curr]) : 0 + payload_ratio = v[:data_curr].nonzero? ? + v[:data_value].to_f * 100 / v[:data_curr] : 0 + bar = ascii_bar(SLAB_FIELDS[:bar][:width] - 2, mem_max, + v[:mem_used], v[:mem_total]) + row = { + :size => k.to_h, + :slab => v[:slab_curr].to_h, + :item => v[:item_curr].to_h, + :item_pct => ("%3.1f%%" % item_ratio), + :data_pct => ("%3.1f%%" % data_ratio), + :payload_pct => ("%3.1f%%" % payload_ratio), + :expire => "%7.1f" % rate[:expire], + :evict => "%7.1f" % rate[:evict], + :slab_evict => "%7.1f" % rate[:slab_evict], + :locate => "%7.1f" % rate[:locate], + :insert => "%7.1f" % rate[:insert], + :bar => (" " + bar + " "), + } + SLAB_ORDER.inject("") { |line, field| line + row[field].rjust(SLAB_FIELDS[field][:width]) } + end + # Summaries + bar = ascii_bar(SLAB_FIELDS[:bar][:width] - 2, mem_max, 0, 0) + row = { + :size => NA, + :slab => slab_total.to_h, + :item => slot_used.to_h, + :item_pct => NA, + :data_pct => NA, + :payload_pct => NA, + :expire => rates.inject(0) { |m, (k, r)| m + r[:expire] }.to_i.to_h, + :evict => rates.inject(0) { |m, (k, r)| m + r[:evict] }.to_i.to_h, + :slab_evict => rates.inject(0) { |m, (k, r)| m + r[:slab_evict] }.to_i.to_h, + :locate => rates.inject(0) { |m, (k, r)| m + r[:locate] }.to_i.to_h, + :insert => rates.inject(0) { |m, (k, r)| m + r[:insert] }.to_i.to_h, + :bar => (" " + bar + " "), + } + $buf.rows << SLAB_ORDER.inject("") { |line, field| line + row[field].rjust(SLAB_FIELDS[field][:width]) } + display +end + +def dump_hosts(hosts, last_hosts=nil) + mem_total = hosts.inject(0) { |m, (n, s)| m + s[:maxbytes] } + mem_used = hosts.inject(0) { |m, (n, s)| m + s[:data] } + total_usage = mem_total.nonzero? ? mem_used.to_f * 100.0 / mem_total : 0.0 + + rates = {} + hosts.each do |name, host| + rate = {} + if last_hosts + last_host = last_hosts[name] + timespan_sec = host[:timestamp] - last_host[:timestamp] + rate[:expire] = (host[:expire] - last_host[:expire]).to_f / timespan_sec + rate[:evict] = (host[:evict] - last_host[:evict]).to_f / timespan_sec + rate[:rdata] = (host[:rdata] - last_host[:rdata]).to_f / timespan_sec + rate[:wdata] = (host[:wdata] - last_host[:wdata]).to_f / timespan_sec + rate[:req] = (host[:req] - last_host[:req]).to_f / timespan_sec + rate[:svrerr] = (host[:svrerr] - last_host[:svrerr]).to_f / timespan_sec + else + rate[:expire] = host[:expire] + rate[:evict] = host[:evict] + rate[:rdata] = host[:rdata] + rate[:wdata] = host[:wdata] + rate[:req] = host[:req] + rate[:svrerr] = host[:svrerr] + end + rates[name] = rate + end + + left_header = " -HOST VIEW- Data size / Available memory: "\ + "#{mem_used.to_h} /#{mem_total.to_h} (#{"%3.1f" % total_usage}%)" + build_headers(left_header, HOST_ORDER, HOST_FIELDS) + + $buf.rows = hosts.map do |host, stats| + server, port = host.split(":") + server = server.length > 15 ? server[0, 15] + "..." : server + rate = rates[host] + row = { + :host => "%18s:%5s" % [server, port], + :uptime => stats[:uptime].to_time_string, + :util => " %3.1f" % (stats[:data].to_f * 100.0 / stats[:maxbytes]), + :conn => stats[:conn].to_h, + :latency => warning_string(stats[:latency], 0.01, :over), + :expire => rate[:expire].to_i.to_h, + :evict => rate[:evict].to_i.to_h, + :rdata => rate[:rdata].to_i.to_h, + :wdata => rate[:wdata].to_i.to_h, + :req => rate[:req].to_i.to_h, + :svrerr => warning_string(rate[:svrerr], 0.01, :over, "%7.1f"), + } + build_row(row, HOST_ORDER, HOST_FIELDS) + end + # Summaries + row = { + :host => "%3d hosts" % hosts.length, + :uptime => NA, + :util => " %3.1f" % total_usage, + :conn => NA, + :latency => NA, + :expire => rates.inject(0) { |m, (n, r)| m + r[:expire] }.to_i.to_h, + :evict => rates.inject(0) { |m, (n, r)| m + r[:evict] }.to_i.to_h, + :rdata => rates.inject(0) { |m, (n, r)| m + r[:rdata] }.to_i.to_h, + :wdata => rates.inject(0) { |m, (n, r)| m + r[:wdata] }.to_i.to_h, + :req => rates.inject(0) { |m, (n, r)| m + r[:req] }.to_i.to_h, + :svrerr => warning_string(rates.inject(0) { |m, (n, r)| m + r[:svrerr]}, 0.01, :over, "%7.1f"), + } + $buf.rows << build_row(row, HOST_ORDER, HOST_FIELDS) + + display +end + +def dump_cmds(cmds, last_cmds=nil) + rates = { + :count => {}, + :error => {}, + :success => {}, + :hit => {}, + :miss => {}, + :exist => {}, + } + if last_cmds + timespan_sec = cmds[:timestamp] - last_cmds[:timestamp] + CMD.each do |cmd| + for category in [:count, :error, :success, :hit, :miss, :exist] + if cmds[category][cmd] + if timespan_sec > 0 + rates[category][cmd] = + (cmds[category][cmd] - last_cmds[category][cmd]).to_f / timespan_sec + else + rates[category][cmd] = 0 + end + end + end + end + else # use absolutes + CMD.each do |cmd| + for category in [:count, :error, :success, :hit, :miss, :exist] + if cmds[category][cmd] + rates[category][cmd] =cmds[category][cmd] + end + end + end + end + cmd_total = rates[:count].inject(0.0) { |n, (k, v)| n += v } + successful = rates[:success].inject(rates[:hit][:delete]) { |n, (k,v)| n += v } + cmd_error = rates[:error].inject(0.0) { |n, (k, v)| n += v } + + # successful commands are _success for most commands and _hit for delete + if cmd_total.nonzero? + success_rate = successful.to_f * 100 / cmd_total + else + success_rate = 0 + end + + left_header = " -COMMAND VIEW- Successful / Total: "\ + "#{successful.to_i.to_h} /#{cmd_total.to_i.to_h} (#{"%3.1f" % success_rate}%)"\ + " Error: #{cmd_error.to_i.to_h}" + build_headers(left_header, CMD_ORDER, CMD_FIELDS) + + $buf.rows = [] + CMD.each do |cmd| + if rates[:count][cmd] > 0 && rates[:success][cmd] + success_ratio = rates[:success][cmd] * 100 / rates[:count][cmd] + else + success_ratio = -1.0 + end + if rates[:count][cmd] > 0 && rates[:hit][cmd] + hit_ratio = rates[:hit][cmd] * 100 / rates[:count][cmd] + else + hit_ratio = -1.0 + end + if rates[:count][cmd] > 0 && rates[:miss][cmd] + miss_ratio = rates[:miss][cmd] * 100 / rates[:count][cmd] + else + miss_ratio = -1.0 + end + if rates[:count][cmd] > 0 && rates[:exist][cmd] + exist_ratio = rates[:exist][cmd] * 100 / rates[:count][cmd] + else + exist_ratio = -1.0 + end + row = { + :command => "%8s" % cmd.id2name, + :rate => "%3.1f" % rates[:count][cmd], + :mix => "%3.1f" % (rates[:count][cmd] * 100 / cmd_total), + :success => (success_ratio > 0) ? warning_string(success_ratio, 90, :under, "%3.1f") : NA, + :hit => (hit_ratio > 0) ? warning_string(hit_ratio, 90, :under, "%3.1f") : NA, + :miss => (miss_ratio > 0) ? "%3.1f" % miss_ratio : NA, + :exist => (exist_ratio > 0) ? "%3.1f" % exist_ratio : NA, + :error => warning_string(rates[:error][cmd], 0, :over, "%7.1f"), + } + $buf.rows << build_row(row, CMD_ORDER, CMD_FIELDS) + end + + # Summaries: read, write, total + if last_cmds + read = CMD_READ.inject(0.0) { |r, c| r += rates[:count][c] } + write = CMD_WRITE.inject(0.0) { |r, c| r += rates[:count][c] } + read_hit = CMD_READ.inject(0.0) { |r, c| r += rates[:hit][c] } + write_success = CMD_WRITE.inject(0.0) { |r, c| r += rates[:success][c] } + read_error = CMD_READ.inject(0.0) { |r, c| r += rates[:error][c] } + write_error = CMD_WRITE.inject(0.0) { |r, c| r += rates[:error][c] } + + row = { + :command => "READ", + :rate => "%3.1f" % read, + :mix => "%3.1f" % ( read * 100 / cmd_total), + :success => NA, + :hit => warning_string(read_hit * 100 / read, 90, :under, "%3.1f"), + :miss => NA, + :exist => NA, + :error => warning_string(read_error, 0, :over, "%7.1f"), + } + $buf.rows << build_row(row, CMD_ORDER, CMD_FIELDS) + row = { + :command => "WRITE", + :rate => "%3.1f" % write, + :mix => "%3.1f" % ( write * 100 / cmd_total), + :success => warning_string(write_success * 100 / write, 99.9, :under, "%3.1f"), + :hit => NA, + :miss => NA, + :exist => NA, + :error => warning_string(write_error, 0, :over, "%7.1f"), + } + $buf.rows << build_row(row, CMD_ORDER, CMD_FIELDS) + row = { + :command => "TOTAL", + :rate => "%3.1f" % cmd_total, + :mix => NA, + :success => NA, + :hit => NA, + :miss => NA, + :exist => NA, + :error => "%3.1f" % cmd_error, + } + $buf.rows << build_row(row, CMD_ORDER, CMD_FIELDS) + end + + display +end + +def load_twemcache_config(filename) + config = YAML.load_file(filename) + blob = if config[$options[:env]] + config[$options[:env]] + elsif config["timeline"] && config["timeline"][$options[:env]] + config["timeline"][$options[:env]] + else + raise "Can't parse yaml for env #{$options[:env]}" + end + if blob["servers"] + $options[:hosts] = blob["servers"].map { |item| item.gsub(/(\S+(?::\d+)):.*/, "\\1") } + else + raise "No servers!" + end +end + +def parse_args + $options = { + :hosts => [ "localhost:11211" ], + :env => "production", + :sleep => 0, + :raw => false, + :view => "slab", # which mode we're showing + } + + opts = OptionParser.new do |opts| + opts.banner = "Usage: mctop [options] [twemcache-config]" + + opts.on("-D", "--dev", "use development config") do + $options[:env] = "development" + end + opts.on("-e", "--env NAME", "use specific environment (like test)") do |env| + $options[:env] = env + end + opts.on("-H", "--host HOST", "connect to one or more specified instance (comma separated, port ranges with a hyphen e.g. host_1:8000-8004,host_2:8000)") do |host| + hosts = host.split(/\s*?,\s*?/) + # Expand port ranges for each host if specified + hosts.map! do |uri| + host, port = uri.split(':') + start_port, end_port = port.split('-') + if end_port + (start_port..end_port).map do |port| + "#{host}:#{port}" + end + else + uri + end + end + + $options[:hosts] = hosts.flatten + end + opts.on("-s", "--sleep N", "stay running, dumping new stats every N seconds") do |n| + $options[:sleep] = n.to_i + end + opts.on("-r", "--raw", "don't use ansi/vt100 codes") do + $options[:raw] = true + end + opts.on("-v", "--view VIEW", "choose among [slab|host|command]") do |view| + $options[:view] = view + end + + opts.on_tail("-h", "--help", "show this message") do + puts opts + exit + end + end + + opts.parse!(ARGV) + load_twemcache_config(ARGV.shift) if ARGV.size > 0 +end + +parse_args +$state = $options[:view] +last_summary = nil +Screen.display do + begin + elapsed = Benchmark.realtime do + host_stats_arr = + $options[:hosts].inject([]) { |list, host| list << ServerStats.new(host) } + summary = SummaryStats.new(host_stats_arr) + + if $state == "slab" + dump_slabs( summary.slabs, last_summary ? last_summary.slabs : nil ) + elsif $state == "host" + dump_hosts( summary.hosts, last_summary ? last_summary.hosts : nil ) + elsif $state == "command" + dump_cmds( summary.cmds, last_summary ? last_summary.cmds : nil ) + else + puts "Invalid viewing mode" + exit + end + last_summary = summary + end + check_key($options[:sleep] > elapsed ? $options[:sleep] - elapsed : 0.1 ) + end while $options[:sleep] > 0 +end diff --git a/src/Makefile.am b/src/Makefile.am index eef5795..f9ab62b 100644 --- a/src/Makefile.am +++ b/src/Makefile.am @@ -1,12 +1,19 @@ +MOSTLYCLEANFILES = *.gcov *.gcno *.gcda *.tcov + bin_PROGRAMS = twemcache -AM_CPPFLAGS = -D_GNU_SOURCE +twemcache_CPPFLAGS = -D_GNU_SOURCE -AM_CFLAGS = -Wall -AM_CFLAGS += -Wmissing-prototypes -Wmissing-declarations -Wredundant-decls -AM_CFLAGS += -fno-strict-aliasing +twemcache_CFLAGS = +twemcache_CFLAGS += -Wall +twemcache_CFLAGS += -Wmissing-prototypes -Wmissing-declarations -Wredundant-decls +twemcache_CFLAGS += -fno-strict-aliasing +twemcache_CFLAGS += @GCOV_CFLAGS@ -LDFLAGS += -rdynamic +twemcache_LDFLAGS = @GCOV_LDFLAGS@ +if RDYNAMIC +twemcache_LDFLAGS += -rdynamic +endif twemcache_SOURCES = \ mc_core.c mc_core.h \ diff --git a/src/mc.c b/src/mc.c index d329114..17fd13e 100644 --- a/src/mc.c +++ b/src/mc.c @@ -85,7 +85,7 @@ #define MC_KLOG_BACKUP NULL #define MC_KLOG_BACKUP_SUF ".old" -#define MC_WORKERS 4 +#define MC_WORKERS 2 #define MC_PID_FILE NULL #define MC_USER NULL @@ -129,6 +129,7 @@ static struct option long_options[] = { { "klog-entry", required_argument, NULL, 'x' }, /* command logging entry number */ { "klog-file", required_argument, NULL, 'X' }, /* command logging file */ { "klog-sample-rate", required_argument, NULL, 'y' }, /* command logging sampling rate */ + { "hash-power", required_argument, NULL, 'e' }, /* fixed sized hash table, as power of 2 */ { "threads", required_argument, NULL, 't' }, /* # of threads */ { "pidfile", required_argument, NULL, 'P' }, /* pid file */ { "user", required_argument, NULL, 'u' }, /* user identity to run as */ diff --git a/src/mc_ascii.c b/src/mc_ascii.c index 1d4bf81..051f269 100644 --- a/src/mc_ascii.c +++ b/src/mc_ascii.c @@ -77,6 +77,9 @@ extern struct settings settings; * COMMAND SUBCOMMAND EVICT_COMMAND * config evict \r\n * + * COMMAND SUBCOMMAND NEW_LIMIT + * config maxbytes \r\n + * * COMMAND SUBCOMMAND KLOG_COMMAND KLOG_SUBCOMMAND * config klog run start\r\n * config klog run stop\r\n @@ -98,6 +101,7 @@ extern struct settings settings; #define TOKEN_CACHEDUMP_LIMIT 3 #define TOKEN_AGGR_COMMAND 2 #define TOKEN_EVICT_COMMAND 2 +#define TOKEN_MAXBYTES_COMMAND 2 #define TOKEN_KLOG_COMMAND 2 #define TOKEN_KLOG_SUBCOMMAND 3 #define TOKEN_MAX 8 @@ -829,6 +833,7 @@ asc_create_suffix(struct conn *c, unsigned valid_key_iter, char **suffix) if (new_suffix_list == NULL) { return MC_ENOMEM; } + stats_thread_incr_by(mem_slist_curr, sizeof(char *) * c->ssize); c->ssize *= 2; c->slist = new_suffix_list; } @@ -992,6 +997,7 @@ asc_process_read(struct conn *c, struct token *token, int ntoken) new_list = mc_realloc(c->ilist, sizeof(struct item *) * c->isize * 2); if (new_list != NULL) { + stats_thread_incr_by(mem_ilist_curr, sizeof(struct item *) * c->isize); c->isize *= 2; c->ilist = new_list; } else { @@ -1587,7 +1593,8 @@ asc_process_evict(struct conn *c, struct token *token, int ntoken) if (!mc_strtol(token[TOKEN_EVICT_COMMAND].val, &option)) { log_debug(LOG_NOTICE, "client error on c %d for req of type %d with " "invalid option '%.*s'", c->sd, c->req_type, - token[TOKEN_EVICT_COMMAND].len,token[TOKEN_EVICT_COMMAND].val); + token[TOKEN_EVICT_COMMAND].len, + token[TOKEN_EVICT_COMMAND].val); asc_rsp_client_error(c); return; @@ -1605,6 +1612,42 @@ asc_process_evict(struct conn *c, struct token *token, int ntoken) asc_rsp_client_error(c); } +static void +asc_process_maxbytes(struct conn *c, struct token *token, int ntoken) +{ + uint64_t option; + + if (ntoken != 4) { + log_hexdump(LOG_NOTICE, c->req, c->req_len, "client error on c %d for " + "req of type %d with %d invalid tokens", c->sd, + c->req_type, ntoken); + + asc_rsp_client_error(c); + return; + } + + if (!mc_strtoull(token[TOKEN_MAXBYTES_COMMAND].val, &option)) { + log_debug(LOG_NOTICE, "client error on c %d for req of type %d with " + "invalid option '%.*s'", c->sd, c->req_type, + token[TOKEN_MAXBYTES_COMMAND].len, + token[TOKEN_MAXBYTES_COMMAND].val); + + asc_rsp_client_error(c); + return; + } + + if (option < SIZE_MAX && option >= settings.maxbytes) { + settings.maxbytes = (size_t)option; + asc_rsp_ok(c); + return; + } + + log_debug(LOG_NOTICE, "client error on c %d for req of type %d with " + "invalid option %"PRId64"", c->sd, c->req_type, option); + + asc_rsp_client_error(c); +} + static void asc_process_config(struct conn *c, struct token *token, int ntoken) { @@ -1616,6 +1659,8 @@ asc_process_config(struct conn *c, struct token *token, int ntoken) asc_process_klog(c, token, ntoken); } else if (strncmp(t->val, "evict", t->len) == 0) { asc_process_evict(c, token, ntoken); + } else if (strncmp(t->val, "maxbytes", t->len) == 0) { + asc_process_maxbytes(c, token, ntoken); } } diff --git a/src/mc_assoc.c b/src/mc_assoc.c index 5b49769..ed49f16 100644 --- a/src/mc_assoc.c +++ b/src/mc_assoc.c @@ -87,6 +87,7 @@ assoc_maintenance_thread(void *arg) if (expand_bucket == HASHSIZE(hash_power - 1)) { expanding = 0; mc_free(old_hashtable); + nbyte_old = 0; } } @@ -186,6 +187,7 @@ assoc_init(void) if (primary_hashtable == NULL) { return MC_ENOMEM; } + nbyte_primary = hashtable_sz * sizeof(struct item_slh); pthread_cond_init(&maintenance_cond, NULL); run_maintenance_thread = 1; @@ -243,11 +245,15 @@ assoc_expand(void) uint32_t hashtable_sz = HASHSIZE(hash_power + 1); old_hashtable = primary_hashtable; + nbyte_old = nbyte_primary; primary_hashtable = assoc_create_table(hashtable_sz); if (primary_hashtable == NULL) { primary_hashtable = old_hashtable; + old_hashtable = NULL; + nbyte_old = 0; return; } + nbyte_primary = hashtable_sz * sizeof(struct item_slh); log_debug(LOG_INFO, "expanding hash table with %"PRIu32" items to " "%"PRIu32" buckets of size %"PRIu32" bytes", nhash_item, diff --git a/src/mc_assoc.h b/src/mc_assoc.h index 5c8c9f6..c1459e0 100644 --- a/src/mc_assoc.h +++ b/src/mc_assoc.h @@ -32,6 +32,9 @@ #define HASH_MAX_POWER 32 +size_t nbyte_primary; +size_t nbyte_old; + rstatus_t assoc_init(void); void assoc_deinit(void); diff --git a/src/mc_cache.c b/src/mc_cache.c index 980c234..8a170ce 100644 --- a/src/mc_cache.c +++ b/src/mc_cache.c @@ -72,6 +72,8 @@ cache_create(const char *name, size_t bufsize, size_t align) ret->name = name_new; ret->ptr = ptr; ret->freetotal = initial_pool_size; + /* we are only tracking memory usage for the variable part of the cache */ + stats_thread_incr_by(mem_cache_curr, sizeof(char *) * ret->freetotal); ret->bufsize = bufsize; @@ -94,9 +96,11 @@ cache_destroy(cache_t *cache) while (cache->freecurr > 0) { void *buf = cache->ptr[--cache->freecurr]; mc_free(buf); + stats_thread_decr_by(mem_cache_curr, cache->bufsize); } mc_free(cache->name); mc_free(cache->ptr); + stats_thread_decr_by(mem_cache_curr, sizeof(char *) * cache->freetotal); pthread_mutex_destroy(&cache->mutex); mc_free(cache); } @@ -118,6 +122,7 @@ cache_alloc(cache_t *cache) object = cache->ptr[--cache->freecurr]; } else { object = mc_alloc(cache->bufsize); + stats_thread_incr_by(mem_cache_curr, cache->bufsize); } pthread_mutex_unlock(&cache->mutex); @@ -145,12 +150,13 @@ cache_free(cache_t *cache, void *buf) size_t newtotal = cache->freetotal * 2; void **new_free = mc_realloc(cache->ptr, sizeof(char *) * newtotal); if (new_free != NULL) { + stats_thread_incr_by(mem_cache_curr, sizeof(char *) * cache->freetotal); cache->freetotal = newtotal; cache->ptr = new_free; cache->ptr[cache->freecurr++] = buf; } else { mc_free(buf); - + stats_thread_decr_by(mem_cache_curr, cache->bufsize); } } pthread_mutex_unlock(&cache->mutex); diff --git a/src/mc_connection.c b/src/mc_connection.c index 6b8d609..6aad043 100644 --- a/src/mc_connection.c +++ b/src/mc_connection.c @@ -100,29 +100,36 @@ conn_free(struct conn *c) } if (c->msg != NULL) { + stats_thread_decr_by(mem_msg_curr, sizeof(*c->msg) * c->msg_size); mc_free(c->msg); } if (c->rbuf != NULL) { + stats_thread_decr_by(mem_rbuf_curr, c->rsize); mc_free(c->rbuf); } if (c->wbuf != NULL) { + stats_thread_decr_by(mem_wbuf_curr, c->wsize); mc_free(c->wbuf); } if (c->ilist != NULL) { + stats_thread_decr_by(mem_ilist_curr, sizeof(*c->ilist) * c->isize); mc_free(c->ilist); } if (c->slist != NULL) { + stats_thread_decr_by(mem_slist_curr, sizeof(*c->slist) * c->ssize); mc_free(c->slist); } if (c->iov != NULL) { + stats_thread_decr_by(mem_iov_curr, sizeof(*c->iov) * c->iov_size); mc_free(c->iov); } + stats_thread_decr_by(mem_conn_curr, sizeof(*c)); mc_free(c); } @@ -131,11 +138,11 @@ conn_put(struct conn *c) { log_debug(LOG_VVERB, "put conn %p c %d", c, c->sd); - if (c->rsize > RSIZE_HIGHWAT) { - conn_free(c); - return; - } + /* Note(yao): disabling free_connq for now */ + conn_free(c); + return; + /* Note(yao): this will not be executed */ pthread_mutex_lock(&free_connq_mutex); nfree_connq++; STAILQ_INSERT_TAIL(&free_connq, c, c_tqe); @@ -203,6 +210,14 @@ conn_get(int sd, conn_state_t state, int ev_flags, int rsize, int udp) return NULL; } + stats_thread_incr_by(mem_conn_curr, sizeof(*c)); + stats_thread_incr_by(mem_rbuf_curr, c->rsize); + stats_thread_incr_by(mem_wbuf_curr, c->wsize); + stats_thread_incr_by(mem_ilist_curr, sizeof(*c->ilist) * c->isize); + stats_thread_incr_by(mem_slist_curr, sizeof(*c->slist) * c->ssize); + stats_thread_incr_by(mem_iov_curr, sizeof(*c->iov) * c->iov_size); + stats_thread_incr_by(mem_msg_curr, sizeof(*c->msg) * c->msg_size); + stats_thread_incr(conn_struct); } @@ -279,6 +294,7 @@ conn_set_event(struct conn *c, struct event_base *base) event_set(&c->event, c->sd, c->ev_flags, core_event_handler, c); event_base_set(base, &c->event); + log_debug(LOG_VERB, "add event %p", &c->event); status = event_add(&c->event, 0); if (status < 0) { return MC_ERROR; @@ -322,9 +338,10 @@ void conn_close(struct conn *c) { /* delete the event, the socket and the conn */ + log_debug(LOG_VERB, "delete event %p", &c->event); event_del(&c->event); - log_debug(LOG_VVERB, "<%d connection closed", c->sd); + log_debug(LOG_VERB, "<%d connection closed", c->sd); close(c->sd); core_accept_conns(true); @@ -361,46 +378,54 @@ conn_shrink(struct conn *c) memmove(c->rbuf, c->rcurr, (size_t)c->rbytes); } + stats_thread_decr_by(mem_rbuf_curr, c->rsize); newbuf = mc_realloc(c->rbuf, TCP_BUFFER_SIZE); if (newbuf != NULL) { c->rbuf = newbuf; c->rsize = TCP_BUFFER_SIZE; } /* TODO check other branch... */ + stats_thread_incr_by(mem_rbuf_curr, c->rsize); c->rcurr = c->rbuf; } if (c->isize > ILIST_HIGHWAT) { struct item **newbuf; + stats_thread_decr_by(mem_ilist_curr, sizeof(*c->ilist) * c->isize); newbuf = mc_realloc(c->ilist, ILIST_SIZE * sizeof(c->ilist[0])); if (newbuf != NULL) { c->ilist = newbuf; c->isize = ILIST_SIZE; } /* TODO check error condition? */ + stats_thread_incr_by(mem_ilist_curr, sizeof(*c->ilist) * c->isize); } if (c->msg_size > MSG_HIGHWAT) { struct msghdr *newbuf; + stats_thread_decr_by(mem_msg_curr, sizeof(*c->msg) * c->msg_size); newbuf = mc_realloc(c->msg, MSG_SIZE * sizeof(c->msg[0])); if (newbuf != NULL) { c->msg = newbuf; c->msg_size = MSG_SIZE; } /* TODO check error condition? */ + stats_thread_incr_by(mem_msg_curr, sizeof(*c->msg) * c->msg_size); } if (c->iov_size > IOV_HIGHWAT) { struct iovec *newbuf; + stats_thread_decr_by(mem_iov_curr, sizeof(*c->iov) * c->iov_size); newbuf = mc_realloc(c->iov, IOV_SIZE * sizeof(c->iov[0])); if (newbuf != NULL) { c->iov = newbuf; c->iov_size = IOV_SIZE; } /* TODO check return value */ + stats_thread_incr_by(mem_iov_curr, IOV_SIZE * sizeof(*c->iov)); } } @@ -443,6 +468,7 @@ conn_ensure_iov_space(struct conn *c) if (new_iov == NULL) { return MC_ENOMEM; } + stats_thread_incr_by(mem_iov_curr, c->iov_size * sizeof(*c->iov)); c->iov = new_iov; c->iov_size *= 2; @@ -540,6 +566,7 @@ conn_add_msghdr(struct conn *c) if (msg == NULL) { return MC_ENOMEM; } + stats_thread_incr_by(mem_msg_curr, c->msg_size * sizeof(*c->msg)); c->msg = msg; c->msg_size *= 2; } diff --git a/src/mc_connection.h b/src/mc_connection.h index 2d0b9d5..66fde80 100644 --- a/src/mc_connection.h +++ b/src/mc_connection.h @@ -38,17 +38,17 @@ #define UDP_BUFFER_SIZE 65536 #define UDP_MAX_PAYLOAD_SIZE 1400 -#define TCP_BUFFER_SIZE 2048 +#define TCP_BUFFER_SIZE 1024 -#define RSIZE_HIGHWAT 8192 +#define RSIZE_HIGHWAT 4096 -#define ILIST_SIZE 200 -#define ILIST_HIGHWAT 400 +#define ILIST_SIZE 20 +#define ILIST_HIGHWAT 40 #define SLIST_SIZE 20 -#define IOV_SIZE 400 -#define IOV_HIGHWAT 600 +#define IOV_SIZE 40 +#define IOV_HIGHWAT 60 #define MSG_SIZE 10 #define MSG_HIGHWAT 100 diff --git a/src/mc_core.c b/src/mc_core.c index f24fbf7..ddb8573 100644 --- a/src/mc_core.c +++ b/src/mc_core.c @@ -204,6 +204,7 @@ core_read_tcp(struct conn *c) c->write_and_go = CONN_CLOSE; return READ_MEMORY_ERROR; } + stats_thread_incr_by(mem_rbuf_curr, c->rsize); c->rcurr = c->rbuf = new_rbuf; c->rsize *= 2; } @@ -230,6 +231,8 @@ core_read_tcp(struct conn *c) } if (errno == EAGAIN || errno == EWOULDBLOCK) { + stats_thread_incr(read_eagain); + log_debug(LOG_VERB, "recv on c %d not ready - eagain", c->sd); break; } @@ -281,6 +284,7 @@ core_update(struct conn *c, int new_flags) return MC_OK; } + log_debug(LOG_VERB, "delete event %p", &c->event); status = event_del(&c->event); if (status < 0) { return MC_ERROR; @@ -290,6 +294,7 @@ core_update(struct conn *c, int new_flags) event_base_set(base, &c->event); c->ev_flags = new_flags; + log_debug(LOG_VERB, "add event %p", &c->event); status = event_add(&c->event, 0); if (status < 0) { return MC_ERROR; @@ -400,8 +405,12 @@ core_transmit(struct conn *c) } if (res == -1 && (errno == EAGAIN || errno == EWOULDBLOCK)) { + stats_thread_incr(write_eagain); + status = core_update(c, EV_WRITE | EV_PERSIST); if (status != MC_OK) { + stats_thread_incr(write_error); + log_error("update on c %d failed: %s", c->sd, strerror(errno)); conn_set_state(c, CONN_CLOSE); return TRANSMIT_HARD_ERROR; @@ -453,21 +462,29 @@ core_accept(struct conn *c) sd = accept(c->sd, NULL, NULL); if (sd < 0) { if (errno == EINTR) { + stats_thread_incr(accept_eintr); + log_debug(LOG_VERB, "accept on s %d not ready - eintr", c->sd); continue; } if (errno == EAGAIN || errno == EWOULDBLOCK) { + stats_thread_incr(accept_eagain); + log_debug(LOG_VERB, "accept on s %d not ready - eagain", c->sd); return; } if (errno == EMFILE || errno == ENFILE) { + stats_thread_incr(accept_emfile); + log_debug(LOG_VERB, "accept on s %d not ready - emfile", c->sd); core_accept_conns(false); return; } + stats_thread_incr(accept_error); + log_error("accept on s %d failed: %s", c->sd, strerror(errno)); return; } @@ -612,8 +629,12 @@ core_drive_machine(struct conn *c) } if (errno == EAGAIN || errno == EWOULDBLOCK) { + stats_thread_incr(read_eagain); + status = core_update(c, EV_READ | EV_PERSIST); if (status != MC_OK) { + stats_thread_incr(read_error); + log_error("update on c %d failed: %s", c->sd, strerror(errno)); conn_set_state(c, CONN_CLOSE); break; @@ -664,6 +685,8 @@ core_drive_machine(struct conn *c) } if (errno == EAGAIN || errno == EWOULDBLOCK) { + stats_thread_incr(read_eagain); + status = core_update(c, EV_READ | EV_PERSIST); if (status != MC_OK) { log_error("update on c %d failed: %s", c->sd, strerror(errno)); diff --git a/src/mc_items.c b/src/mc_items.c index 5cb7306..1d164e0 100644 --- a/src/mc_items.c +++ b/src/mc_items.c @@ -647,7 +647,7 @@ _item_get(const char *key, size_t nkey) if (settings.oldest_live != 0 && settings.oldest_live <= time_now() && it->atime <= settings.oldest_live) { _item_unlink(it); - stats_slab_incr(it->id, item_evict); + stats_slab_incr(it->id, item_expire); log_debug(LOG_VERB, "it '%.*s' nuked", nkey, key); return NULL; } diff --git a/src/mc_log.c b/src/mc_log.c index 68bcaeb..f17950f 100644 --- a/src/mc_log.c +++ b/src/mc_log.c @@ -36,6 +36,7 @@ #include +extern struct settings settings; static struct logger logger; int @@ -78,7 +79,7 @@ log_reopen(void) close(l->fd); l->fd = open(l->name, O_WRONLY | O_APPEND | O_CREAT, 0644); if (l->fd < 0) { - log_stderr("reopening log file '%s' failed, ignored: %s", l->name, + log_stderr_safe("reopening log file '%s' failed, ignored: %s", l->name, strerror(errno)); } } @@ -91,7 +92,8 @@ log_level_up(void) if (l->level < LOG_PVERB) { l->level++; - loga("up log level to %d", l->level); + settings.verbose = l->level; + log_safe("up log level to %d", l->level); } } @@ -102,7 +104,8 @@ log_level_down(void) if (l->level > LOG_EMERG) { l->level--; - loga("down log level to %d", l->level); + settings.verbose = l->level; + log_safe("down log level to %d", l->level); } } @@ -112,9 +115,22 @@ log_level_set(int level) struct logger *l = &logger; l->level = MAX(LOG_EMERG, MIN(level, LOG_PVERB)); + settings.verbose = l->level; loga("set log level to %d", l->level); } +void +log_stacktrace(void) +{ + struct logger *l = &logger; + + if (l->fd < 0) { + return; + } + + mc_stacktrace_fd(l->fd); +} + int log_loggable(int level) { @@ -261,3 +277,70 @@ _log_hexdump(char *data, int datalen) errno = errno_save; } + +void +_log_safe(const char *fmt, ...) +{ + struct logger *l = &logger; + int len, size, errno_save; + char buf[LOG_MAX_LEN]; + va_list args; + ssize_t n; + + if (l->fd < 0) { + return; + } + + errno_save = errno; + len = 0; /* length of output buffer */ + size = LOG_MAX_LEN; /* size of output buffer */ + + /* to avoid localtime(), which is not thread safe, skip timestamp for now */ + len += mc_safe_snprintf(buf + len, size - len, + "[........................] "); + + va_start(args, fmt); + len += mc_safe_vsnprintf(buf + len, size - len, fmt, args); + va_end(args); + + buf[len++] = '\n'; + + n = mc_write(l->fd, buf, len); + if (n < 0) { + l->nerror++; + } + + errno = errno_save; +} + +void +_log_stderr_safe(const char *fmt, ...) + +{ + struct logger *l = &logger; + int len, size, errno_save; + char buf[LOG_MAX_LEN]; + va_list args; + ssize_t n; + + errno_save = errno; + len = 0; /* length of output buffer */ + size = LOG_MAX_LEN; /* size of output buffer */ + + len += mc_safe_snprintf(buf + len, size - len, + "[........................] "); + + va_start(args, fmt); + len += mc_safe_vsnprintf(buf + len, size - len, fmt, args); + va_end(args); + + buf[len++] = '\n'; + + n = mc_write(STDERR_FILENO, buf, len); + if (n < 0) { + l->nerror++; + } + + errno = errno_save; +} + diff --git a/src/mc_log.h b/src/mc_log.h index 47d5c5c..8dbbbcd 100644 --- a/src/mc_log.h +++ b/src/mc_log.h @@ -116,15 +116,27 @@ struct logger { } \ } while (0) +#define log_safe(...) do { \ + _log_safe(__VA_ARGS__); \ +} while (0) + +#define log_stderr_safe(...) do { \ + _log_stderr_safe(__VA_ARGS__); \ +} while (0) + + int log_init(int level, char *filename); void log_deinit(void); void log_level_up(void); void log_level_down(void); void log_level_set(int level); +void log_stacktrace(void); void log_reopen(void); int log_loggable(int level); void _log(const char *file, int line, int panic, const char *fmt, ...); void _log_stderr(const char *fmt, ...); void _log_hexdump(char *data, int datalen); +void _log_safe(const char *fmt, ...); +void _log_stderr_safe(const char *fmt, ...); #endif diff --git a/src/mc_queue.h b/src/mc_queue.h index 0186e82..bc7e617 100644 --- a/src/mc_queue.h +++ b/src/mc_queue.h @@ -64,7 +64,9 @@ #include +#ifndef __offsetof #define __offsetof(type, field) ((size_t)(&((type *)NULL)->field)) +#endif /* * This file defines five types of data structures: singly-linked lists, diff --git a/src/mc_signal.c b/src/mc_signal.c index 80221c7..c29b781 100644 --- a/src/mc_signal.c +++ b/src/mc_signal.c @@ -39,11 +39,16 @@ static struct signal signals[] = { { SIGTTOU, "SIGTTOU", 0, signal_handler }, { SIGHUP, "SIGHUP", 0, signal_handler }, { SIGINT, "SIGINT", 0, signal_handler }, + { SIGTERM, "SIGTERM", 0, signal_handler }, { SIGSEGV, "SIGSEGV", SA_RESETHAND, signal_handler }, { SIGPIPE, "SIGPIPE", 0, SIG_IGN }, { 0, NULL, 0, NULL } }; +#ifdef HAVE_GCOV +void __gcov_flush(void); +#endif + rstatus_t signal_init(void) { @@ -119,6 +124,7 @@ signal_handler(int signo) break; case SIGINT: + case SIGTERM: done = true; actionstr = ", exiting"; break; @@ -141,6 +147,9 @@ signal_handler(int signo) } if (done) { +#ifdef HAVE_GCOV + __gcov_flush(); +#endif exit(1); } } diff --git a/src/mc_stats.c b/src/mc_stats.c index 7f88a32..76ae61e 100644 --- a/src/mc_stats.c +++ b/src/mc_stats.c @@ -48,7 +48,7 @@ extern pthread_mutex_t cache_lock; #define STATS_BUCKET_SIZE 32 #define MAKEARRAY(_name, _type, _desc) \ - { .type = _type, .value = { .counter = 0LL }, .name = #_name }, + { .type = _type, .value = { .gauge = {0LL, 0LL } }, .name = #_name }, static struct stats_metric stats_tmetrics[] = { STATS_THREAD_METRICS(MAKEARRAY) }; @@ -58,6 +58,17 @@ static struct stats_metric stats_smetrics[] = { }; #undef MAKEARRAY +/* + * currently for max we only deal with thread-level stats, as we haven't found + * use for slab level metrics yet. + */ +#define MAKEMAXARRAY(_name, _type, _desc) \ + { .type = STATS_MAX, .value = { .max = 0LL }, .name = #_name }, +static struct stats_metric stats_tmax[] = { + STATS_THREAD_METRICS(MAKEMAXARRAY) +}; +#undef MAKEMAXARRAY + static int num_updaters; /* # threads that update stats */ struct stats_desc { @@ -147,6 +158,10 @@ stats_metric_init(struct stats_metric *metric) metric->value.gauge.b = 0LL; break; + case STATS_MAX: + metric->value.max = 0LL; + break; + default: NOT_REACHED(); } @@ -164,6 +179,12 @@ stats_template_init(void) for (i = 0; i < STATS_SLAB_LEN; ++i) { stats_metric_init(&stats_smetrics[i]); } + + for (i = 0; i < STATS_THREAD_LEN; ++i) { + stats_metric_init(&stats_tmax[i]); + } + + /* skipping slab level max for now */ } void @@ -296,6 +317,9 @@ stats_metric_val(struct stats_metric *metric) delta = metric->value.gauge.t - metric->value.gauge.b; return delta >= 0 ? delta : 0; + case STATS_MAX: + return metric->value.max; + default: NOT_REACHED(); return -1; @@ -312,7 +336,9 @@ stats_metric_update(struct stats_metric *metric1, { ASSERT(metric1 != NULL); ASSERT(metric2 != NULL); - ASSERT(metric1->type == metric2->type); + ASSERT(metric1->type == metric2->type || metric1->type == STATS_MAX); + + int64_t val; switch (metric1->type) { case STATS_COUNTER: @@ -322,6 +348,12 @@ stats_metric_update(struct stats_metric *metric1, case STATS_GAUGE: metric1->value.gauge.t += metric2->value.gauge.t; metric1->value.gauge.b += metric2->value.gauge.b; + + case STATS_MAX: /* MAX exists at the global level for gauges only */ + val = metric2->value.gauge.t - metric2->value.gauge.b; + if (metric1->value.max < val) { + metric1->value.max = val; + } break; default: @@ -464,7 +496,7 @@ _stats_aggregate(void) /* this is to reset connection related stats before aggregation */ memcpy(aggregator.stats_thread, stats_tmetrics, - 5 * sizeof(struct stats_metric)); + STATS_THREAD_LEN * sizeof(struct stats_metric)); for (cid = 0; cid <= SLABCLASS_MAX_ID; ++cid) { /* cid 0: aggregated */ stats_slab_reset(aggregator.stats_slabs[cid]); } @@ -504,6 +536,13 @@ _stats_aggregate(void) for (i = 0; i < num_updaters; ++i) { sem_post(&aggregator.stats_sem); } + + /* update thread-level max */ + for (j = 0; j < STATS_THREAD_LEN; ++j) { + stats_metric_update(&stats_tmax[j], &aggregator.stats_thread[j]); + } + + /* skipping slab-level max for now */ } /* @@ -642,6 +681,7 @@ stats_default(struct conn *c) struct rusage usage; rel_time_t uptime; long int abstime; + char name[64]; uptime = time_now(); abstime = (long int)time_started() + time_now(); @@ -662,17 +702,27 @@ stats_default(struct conn *c) usage.ru_utime.tv_usec); stats_print(c, "rusage_system", "%ld.%06ld", usage.ru_stime.tv_sec, usage.ru_stime.tv_usec); + stats_print(c, "rusage_maxrss", "%ld", usage.ru_maxrss); + stats_print(c, "rusage_nvcsw", "%ld", usage.ru_nvcsw); + stats_print(c, "rusage_nivcsw", "%ld", usage.ru_nivcsw); + stats_print(c, "nbyte_primary", "%zu", nbyte_primary); + stats_print(c, "nbyte_old", "%zu", nbyte_old); sem_wait(&aggregator.stats_sem); /* thread-level metrics */ for (i = 0; i < STATS_THREAD_LEN; ++i) { stats_print(c, thread[i].name, "%"PRId64, stats_metric_val(&thread[i])); + if (thread[i].type == STATS_GAUGE) { + mc_snprintf(name, 63, "%s_max", stats_tmax[i].name); + stats_print(c, name, "%"PRId64, stats_metric_val(&stats_tmax[i])); + } } /* slab-level metrics, summary */ for (i = 0; i < STATS_SLAB_LEN; ++i) { stats_print(c, slab[i].name, "%"PRId64, stats_metric_val(&slab[i])); + /* skipping slab-level max */ } sem_post(&aggregator.stats_sem); diff --git a/src/mc_stats.h b/src/mc_stats.h index 61f9cb8..ac0b9b6 100644 --- a/src/mc_stats.h +++ b/src/mc_stats.h @@ -83,7 +83,22 @@ ACTION( klog_logged, STATS_COUNTER, "# commands logged in buffer when klog is turned on") \ ACTION( klog_discarded, STATS_COUNTER, "# commands discarded when klog is turned on") \ ACTION( klog_skipped, STATS_COUNTER, "# commands skipped by sampling when klog is turned on")\ - + ACTION( accept_eagain, STATS_COUNTER, "# EAGAIN when calling accept()") \ + ACTION( accept_eintr, STATS_COUNTER, "# EINTR when calling accept()") \ + ACTION( accept_emfile, STATS_COUNTER, "# EMFILE when calling accept()") \ + ACTION( accept_error, STATS_COUNTER, "# unhandled errors when calling accept()") \ + ACTION( read_eagain, STATS_COUNTER, "# EAGAIN on the socket read paths") \ + ACTION( read_error, STATS_COUNTER, "# unhandled errors on the socket read paths") \ + ACTION( write_eagain, STATS_COUNTER, "# EAGAIN on the socket write paths") \ + ACTION( write_error, STATS_COUNTER, "# unhandled errors on the socket write paths") \ + ACTION( mem_conn_curr, STATS_GAUGE, "# bytes used by struct conn") \ + ACTION( mem_rbuf_curr, STATS_GAUGE, "# bytes used by conn rbuf") \ + ACTION( mem_wbuf_curr, STATS_GAUGE, "# bytes used by conn wbuf") \ + ACTION( mem_ilist_curr, STATS_GAUGE, "# bytes used by conn ilist") \ + ACTION( mem_slist_curr, STATS_GAUGE, "# bytes used by conn slist") \ + ACTION( mem_iov_curr, STATS_GAUGE, "# bytes used by conn iov") \ + ACTION( mem_msg_curr, STATS_GAUGE, "# bytes used by conn msg") \ + ACTION( mem_cache_curr, STATS_GAUGE, "# bytes used by object cache") \ #define STATS_SLAB_METRICS(ACTION) \ ACTION( data_curr, STATS_GAUGE, "# current item bytes including overhead") \ @@ -123,7 +138,8 @@ typedef enum metric_type { STATS_INVALID, /* invalid or uninitialized */ STATS_COUNTER, /* monotonic accumulator */ - STATS_GAUGE /* non-monotonic accumulator */ + STATS_GAUGE, /* non-monotonic accumulator */ + STATS_MAX /* max, monotonic */ } metric_type_t; struct stats_metric { @@ -135,6 +151,7 @@ struct stats_metric { int64_t t; /* incr counter */ int64_t b; /* decr counter */ } gauge; + int64_t max; /* max, only applicable on aggregated gauge */ } value; }; diff --git a/src/mc_util.c b/src/mc_util.c index 169332f..829bb5b 100644 --- a/src/mc_util.c +++ b/src/mc_util.c @@ -34,9 +34,12 @@ #include #include #include +#include #include +static const char HEX[] = "0123456789abcdef"; + int mc_set_blocking(int sd) { @@ -578,6 +581,18 @@ mc_stacktrace(int skip_count) #endif } +void +mc_stacktrace_fd(int fd) +{ +#ifdef MC_BACKTRACE + void *stack[64]; + int size; + + size = backtrace(stack, 64); + backtrace_symbols_fd(stack, size, fd); +#endif +} + void mc_resolve_peer(int sd, char *buf, int size) { @@ -651,3 +666,177 @@ mc_resolve_peer(int sd, char *buf, int size) error: mc_snprintf(buf, size, "%s", "-"); } + +static char * +safe_utoa(int _base, uint64_t val, char *buf) +{ + uint32_t base = (uint32_t) _base; + *buf-- = 0; + do { + *buf-- = HEX[val % base]; + } while ((val /= base) != 0); + return buf + 1; +} + +static char * +safe_itoa(int base, int64_t val, char *buf) +{ + char *orig_buf = buf; + const int32_t is_neg = (val < 0); + *buf-- = 0; + + if (is_neg) { + val = -val; + } + if (is_neg && base == 16) { + int ix; + val -= 1; + for (ix = 0; ix < 16; ++ix) + buf[-ix] = '0'; + } + + do { + *buf-- = HEX[val % base]; + } while ((val /= base) != 0); + + if (is_neg && base == 10) { + *buf-- = '-'; + } + + if (is_neg && base == 16) { + int ix; + buf = orig_buf - 1; + for (ix = 0; ix < 16; ++ix, --buf) { + /* *INDENT-OFF* */ + switch (*buf) { + case '0': *buf = 'f'; break; + case '1': *buf = 'e'; break; + case '2': *buf = 'd'; break; + case '3': *buf = 'c'; break; + case '4': *buf = 'b'; break; + case '5': *buf = 'a'; break; + case '6': *buf = '9'; break; + case '7': *buf = '8'; break; + case '8': *buf = '7'; break; + case '9': *buf = '6'; break; + case 'a': *buf = '5'; break; + case 'b': *buf = '4'; break; + case 'c': *buf = '3'; break; + case 'd': *buf = '2'; break; + case 'e': *buf = '1'; break; + case 'f': *buf = '0'; break; + } + /* *INDENT-ON* */ + } + } + return buf + 1; +} + +static const char * +safe_check_longlong(const char *fmt, int32_t * have_longlong) +{ + *have_longlong = false; + if (*fmt == 'l') { + fmt++; + if (*fmt != 'l') { + *have_longlong = (sizeof(long) == sizeof(int64_t)); + } else { + fmt++; + *have_longlong = true; + } + } + return fmt; +} + +int +_safe_vsnprintf(char *to, size_t size, const char *format, va_list ap) +{ + char *start = to; + char *end = start + size - 1; + for (; *format; ++format) { + int32_t have_longlong = false; + if (*format != '%') { + if (to == end) { /* end of buffer */ + break; + } + *to++ = *format; /* copy ordinary char */ + continue; + } + ++format; /* skip '%' */ + + format = safe_check_longlong(format, &have_longlong); + + switch (*format) { + case 'd': + case 'i': + case 'u': + case 'x': + case 'p': + { + int64_t ival = 0; + uint64_t uval = 0; + if (*format == 'p') + have_longlong = (sizeof(void *) == sizeof(uint64_t)); + if (have_longlong) { + if (*format == 'u') { + uval = va_arg(ap, uint64_t); + } else { + ival = va_arg(ap, int64_t); + } + } else { + if (*format == 'u') { + uval = va_arg(ap, uint32_t); + } else { + ival = va_arg(ap, int32_t); + } + } + + { + char buff[22]; + const int base = (*format == 'x' || *format == 'p') ? 16 : 10; + +/* *INDENT-OFF* */ + char *val_as_str = (*format == 'u') ? + safe_utoa(base, uval, &buff[sizeof(buff) - 1]) : + safe_itoa(base, ival, &buff[sizeof(buff) - 1]); +/* *INDENT-ON* */ + + /* Strip off "ffffffff" if we have 'x' format without 'll' */ + if (*format == 'x' && !have_longlong && ival < 0) { + val_as_str += 8; + } + + while (*val_as_str && to < end) { + *to++ = *val_as_str++; + } + continue; + } + } + case 's': + { + const char *val = va_arg(ap, char *); + if (!val) { + val = "(null)"; + } + while (*val && to < end) { + *to++ = *val++; + } + continue; + } + } + } + *to = 0; + return (int)(to - start); +} + +int +_safe_snprintf(char *to, size_t n, const char *fmt, ...) +{ + int result; + va_list args; + va_start(args, fmt); + result = _safe_vsnprintf(to, n, fmt, args); + va_end(args); + return result; +} + diff --git a/src/mc_util.h b/src/mc_util.h index 20e2153..9657e6a 100644 --- a/src/mc_util.h +++ b/src/mc_util.h @@ -185,6 +185,7 @@ bool mc_str2oct(const char *str, int32_t *out); #endif void mc_stacktrace(int skip_count); +void mc_stacktrace_fd(int fd); void mc_assert(const char *cond, const char *file, int line, int panic); #define mc_strlen(_s) strlen((const char *)(_s)) @@ -196,6 +197,25 @@ void mc_assert(const char *cond, const char *file, int line, int panic); #define mc_scnprintf(_s, _n, ...) _scnprintf((char *)_s, _n, __VA_ARGS__) #define mc_vscnprintf(_s, _n, _f, _a) _vscnprintf((char*) _s, _n, _f, _a) +/** + A (very) limited version of snprintf. + @param to Destination buffer. + @param size Size of destination buffer. + @param fmt printf() style format string. + @returns Number of bytes written, including terminating '\0' + Supports 'd' 'i' 'u' 'x' 'p' 's' conversion. + Supports 'l' and 'll' modifiers for integral types. + Does not support any width/precision. + Implemented with simplicity, and async-signal-safety in mind. +*/ +int _safe_vsnprintf(char *to, size_t size, const char *fmt, va_list ap); +int _safe_snprintf(char *to, size_t size, const char *fmt, ...); + +#define mc_safe_snprintf(_s, _n, ...) \ + _safe_snprintf((char *)(_s), (size_t)(_n), __VA_ARGS__) +#define mc_safe_vsnprintf(_s, _n, _f, _a) \ + _safe_vsnprintf((char *)(_s), (size_t)(_n), _f, _a) + int _scnprintf(char *buf, size_t size, const char *fmt, ...); int _vscnprintf(char *buf, size_t size, const char *fmt, va_list args); diff --git a/tests/config/server/default-template.py b/tests/config/server/default-template.py index 474082f..40f5338 100644 --- a/tests/config/server/default-template.py +++ b/tests/config/server/default-template.py @@ -91,9 +91,10 @@ # global stats (returns of "stats" command) STATS_KEYS = [ # system/service info 'pid', 'uptime', 'time', 'version', 'pointer_size', 'aggregate_ts', - 'rusage_user', 'rusage_system', + 'rusage_user', 'rusage_system', 'rusage_maxrss', 'rusage_nvcsw', 'rusage_nivcsw', + 'nbyte_primary', 'nbyte_old', # connection related - 'conn_disabled', 'conn_total', 'conn_struct', 'conn_yield', 'conn_curr', + 'conn_disabled', 'conn_total', 'conn_struct', 'conn_yield', 'conn_curr', 'conn_curr_max', # item/slab related 'item_curr', 'item_free', 'item_acquire', 'item_remove', 'item_link', 'item_unlink', 'item_evict', 'item_expire', 'slab_req', 'slab_error', 'slab_alloc', 'slab_curr', 'slab_evict', @@ -116,7 +117,14 @@ 'cmd_total', # general errors 'cmd_error', 'server_error', - 'klog_logged', 'klog_discarded', 'klog_skipped' + 'accept_eagain', 'accept_eintr', 'accept_emfile', 'accept_error', + 'read_eagain', 'read_error', 'write_eagain', 'write_error', + 'klog_logged', 'klog_discarded', 'klog_skipped', + # memory related + 'mem_cache_curr', 'mem_conn_curr', 'mem_rbuf_curr', 'mem_wbuf_curr', + 'mem_cache_curr_max', 'mem_conn_curr_max', 'mem_rbuf_curr_max', 'mem_wbuf_curr_max', + 'mem_ilist_curr', 'mem_slist_curr', 'mem_iov_curr', 'mem_msg_curr', + 'mem_ilist_curr_max', 'mem_slist_curr_max', 'mem_iov_curr_max', 'mem_msg_curr_max' ] SETTINGS_KEYS = [ 'prealloc', 'lock_page', 'accepting_conns', 'daemonize', 'max_corefile', diff --git a/tests/lib/utilities.py b/tests/lib/utilities.py index 255488f..b7dc34a 100644 --- a/tests/lib/utilities.py +++ b/tests/lib/utilities.py @@ -49,7 +49,7 @@ def startServer(args=None): def stopServer(server=None): '''shutdown twemcache''' if server != None: - server.kill() + server.terminate() time.sleep(SHUTDOWN_DELAY) print_verbose("Stopped twemcache instance, pid %d\n" % server.pid, VERBOSE) diff --git a/tests/protocol/badbasic.py b/tests/protocol/badbasic.py index 4b439f3..474504c 100644 --- a/tests/protocol/badbasic.py +++ b/tests/protocol/badbasic.py @@ -90,7 +90,8 @@ def test_longkey(self): key_len = 500 key = 'a' * key_len server.send_cmd("get {0}\r\n".format(key)) # looooooong key - self.assertEqual("CLIENT_ERROR", server.expect("CLIENT_ERROR")) + err_string = "CLIENT_ERROR" + self.assertEqual(err_string, server.expect(err_string)) def test_largevalue(self): '''Append/prepend grows item out of size range.''' diff --git a/tests/protocol/badstartup.py b/tests/protocol/badstartup.py index a0e3f92..6c57b2e 100644 --- a/tests/protocol/badstartup.py +++ b/tests/protocol/badstartup.py @@ -62,6 +62,7 @@ def test_badhost(self): self.server = startServer(args) time.sleep(SHUTDOWN_DELAY) # give the process enough time to finish up self.server.poll() + print self.server.returncode self.assertIsNotNone(self.server.returncode) #termination means error def test_badthread(self):