Re: [PATCH] Add ext3 data=guarded mode

[Jan Kara]

On Mon 20-04-09 11:07:17, Mike Galbraith wrote:
> On Sun, 2009-04-19 at 11:54 +0530, Amit Shah wrote:
> > On (Sat) Apr 18 2009 [09:28:21], Mike Galbraith wrote:
> 
> > > Probably because you're swapping heavily, and that is perturbing your
> > 
> > The variance only affects the 4k test; the other times more or less
> > remain the same.
> 
> My box disagrees.
> 
> (bumps ulimits to test 4BG... OS+swap live on sdb btw)
> 
> ./test-file-zero-alloc-speed 4 /dev/sdf3 /media/root ext3 rw,_netdev,noatime,data=foo,acl,user_xattr
> 
> foo=guarded
> 4k   225  141   80  142  361
> 8k    74   96  362   78   84
> mm    55   57   57   57   57
> 
> foo=writeback
> 4k   179  264  187  125   93
> 8k    94  161   73  334   84
> mm    57   58   57   56   57
> 
> foo=ordered
> 4k    81   74   76   80   75
> 8k    77   76  224   79   79 
> mm    59   56   60   58   59
> 
> foo=journal
> 4k    95  297   69   83  420
> 8k    73  139  158   80   78
> mm    57   58   56   59   56
> 
> ./test-file-zero-alloc-speed 2 /dev/sdf3 /media/root ext3 rw,_netdev,noatime,data=foo,acl,user_xattr
> 
> foo=guarded
> 4k    28   27   27   28   28
> 8k    28   27   27   28   27
> 
> foo=writeback
> 4k    27   27   27   27   27
> 8k    28   28   27   27   28
> 
> All journal modes seem subject to bad throughput under heavy pressure,
> though data=ordered seems much less likely to suffer for some reason.
> Major difference _seems_ to be that write()+largefile induces very much
> swap activity.
  My rough guess is that this depends on the VM writeout behavior. In
ordered mode, we forcibly writeout all the dirty data on a transaction
commit which happens every 5 seconds so they don't accumulate that much.
In other journaling modes we don't do that and decisions about writeout
(probably how much pdflush manages to write in background vs. how much
VM throttles the process to do the writeback itself) cause variances in
the run time. But this is just a guess. You could gather blktraces of
slow and fast runs and then look if the amount of IO done by different
processes significantly differs. If Chris has merged by improvements to
Seekwatcher, then you could nicely visualize this (hmm, that doesn't seem
to be the case so I'm attaching the diff and a helper script - see comments
in the beginning of the script and command helps for usage).

								Honza
-- 
Jan Kara <jack@xxxxxxx>
SUSE Labs, CR
--- seekwatcher.orig	2009-01-15 00:04:20.000000000 +0100
+++ seekwatcher	2009-01-26 12:04:21.000000000 +0100
@@ -56,6 +56,7 @@
 from optparse import OptionParser
 
 blktrace_only = False
+tags = { "": 0 }
 
 try:
     from matplotlib import rcParams
@@ -136,9 +137,9 @@
     return 2.0
     sys.stderr.write("unknown command %s\n" % com)
 
-def loaddata(fh,delimiter=None, converters=None):
+def loaddata(fh,delimiter=None, converters=None, filter=True):
 
-    def iter(fh, delimiter, converters):
+    def iter(fh, delimiter, converters, filter):
         global devices_sector_max
 
         if converters is None: converters = {}
@@ -149,10 +150,20 @@
         last_cmd = None
         last_size = None
         last_dev = None
+        last_tag = None
         for i,line in enumerate(fh):
-            if not line.startswith('C'):
+            if filter and not line.startswith('C'):
                 continue
-            row = [converters.get(i,float)(val) for i,val in enumerate(line.split(delimiter))]
+            if not filter:
+                line = "C " + line
+            this_tag = 0
+            row = []
+            for i,val in enumerate(line.split(delimiter)):
+                if i < 9:
+                    row.append(converters.get(i,float)(val))
+                else:
+		    this_tag = tags.setdefault(val, len(tags))
+            row.append(this_tag)
             this_time = row[7]
             this_dev = row[8]
             this_sector = row[4]
@@ -165,7 +176,7 @@
             if (last_row and this_rw == last_rw and
                 this_dev == last_dev and
                 this_time - last_time < .5 and last_size < 512 and
-                this_sector == last_end):
+                this_sector == last_end and this_tag == last_tag):
                 last_end += this_size
                 last_size += this_size
                 last_row[5] += row[5]
@@ -182,11 +193,12 @@
             last_end = this_sector + this_size
             last_size = this_size
             last_dev = this_dev
+            last_tag = this_tag
         if last_row:
             for x in last_row:
                 yield x
 
-    X = numpy.fromiter(iter(fh, delimiter, converters), dtype=float)
+    X = numpy.fromiter(iter(fh, delimiter, converters, filter), dtype=float)
     return X
 
 def sort_by_time(data):
@@ -367,7 +379,7 @@
             os.remove(os.path.join(root, name))
     os.rmdir(png_dir)
 
-def plot_data(ax, rw, data, style, label, alpha=1):
+def plot_data(ax, data, style, label, alpha=1):
     def reduce_plot():
         reduce = {}
         skipped = 0
@@ -380,37 +392,48 @@
             y += 1
             h = reduce.setdefault(x, {})
             h[y] = 1
+            yield rbs[i]
             yield x * x_per_cell
             yield y * y_per_cell
+            yield tg[i]
     xcells = 325.0 * options.io_graph_cell_multi
     x_per_cell = (xmax - xmin) / xcells
     ycells = 80.0 * options.io_graph_cell_multi
     y_per_cell = (yzoommax - yzoommin) / ycells
 
-    if rw is None:
-        if options.reads_only:
-            rw = 0
-        if options.writes_only:
-            rw = 1
-    if rw != None:
-        if options.reads_only and rw != 0:
-            return
-        if options.writes_only and rw != 1:
-            return
-        rbs = data[:,1]
-        data = data[numpy.where(rbs == rw)]
+    rbs = data[:,1]
+    if options.reads_only:
+        data = data[numpy.where(rbs == 0)]
+    if options.writes_only:
+        data = data[numpy.where(rbs == 1)]
+
+    if len(data) == 0:
+        return []
+
     times = data[:,7]
     sectors = data[:,4]
-    if len(times) > 0:
-        t = numpy.fromiter(reduce_plot(), dtype=float)
-        t.shape = (len(t)/2, 2)
-        xdata = t[:,0]
-        ydata = t[:,1]
-        lines = ax.plot(t[:,0], t[:,1], options.io_graph_dots, mew=0,
-                        ms=options.io_graph_marker_size,
-                        label=label, alpha=alpha)
-        return lines
-    return []
+    tg = data[:,9]
+    t = numpy.fromiter(reduce_plot(), dtype=float)
+    t.shape = (len(t)/4, 4)
+    lines = []
+    for tag in tags:
+        at = t[numpy.where(t[:,3] == tags[tag])]
+        if len(at) == 0:
+            continue
+        if not options.writes_only:
+            atr = at[numpy.where(at[:,0] == 0)]
+            lines.extend(ax.plot(atr[:,1], atr[:,2], style, mew=0,
+                                 ms=options.io_graph_marker_size,
+                                 alpha=alpha,
+                                 label=tag + " Reads " + label))
+        if not options.reads_only:
+            atr = at[numpy.where(at[:,0] == 1)]
+            lines.extend(ax.plot(atr[:,1], atr[:,2], style, mew=0,
+                                 ms=options.io_graph_marker_size,
+                                 alpha=alpha,
+                                 label=tag + " Writes " + label))
+    return lines
+
 
 def add_roll(roll, max, num):
     if len(roll) == max:
@@ -624,11 +647,11 @@
     return data
 
 def shapeit(X):
-    lines = len(X) / 9
-    X.shape = (lines, 9)
+    lines = len(X) / 10
+    X.shape = (lines, 10)
 
 def unshapeit(X):
-    lines = len(X) * 9
+    lines = len(X) * 10
     X.shape = (lines, 1)
 
 def getlabel(i):
@@ -692,12 +715,49 @@
 def translate_sector(dev, sector):
     return device_translate[dev] + sector;
 
+def process_input(input, type):
+    global devices_sector_max
+    global device_translate
+    global must_sort
+
+    devices_sector_max = {}
+    if type == 0:
+        run = run_blkparse(input, converters)
+    elif type == 1:
+        if input == "-":
+            p = sys.stdin
+        else:
+            p = open(input, 'r')
+        run = loaddata(p, converters=converters, filter=False)
+
+    device_translate = {}
+    total = 0
+    if len(devices_sector_max) > 1:
+        must_sort = True
+        for x in devices_sector_max:
+            device_translate[x] = total + devices_sector_max[x]
+            total += devices_sector_max[x]
+    shapeit(run)
+    if len(devices_sector_max) > 1:
+        for x in run:
+            sector = x[4]
+            dev = x[8]
+            x[4] = device_translate[dev] + sector
+        
+    sorted = sort_by_time(run)
+    run = sorted
+
+    unshapeit(run)
+    return run
+
 usage = "usage: %prog [options]"
 parser = OptionParser(usage=usage)
 parser.add_option("-d", "--device", help="Device for blktrace", default=[],
                   action="append")
 parser.add_option("-t", "--trace", help="blktrace file", default=[],
                   action="append")
+parser.add_option("-f", "--file", help="parsed blktrace file", default=[],
+                  action="append")
 parser.add_option("-p", "--prog", help="exec program", default="")
 parser.add_option("", "--full-trace", help="Don't filter blktrace events",
                   default=False, action="store_true")
@@ -710,7 +770,7 @@
     parser.add_option("-o", "--output", help="output file", default="trace.png")
     parser.add_option("-l", "--label", help="label", default=[],
                       action="append")
-    parser.add_option("", "--dpi", help="dpi", default=120)
+    parser.add_option("", "--dpi", help="dpi", default=120, type="float")
     parser.add_option("", "--io-graph-dots", help="Disk IO dot style",
                       default='s')
     parser.add_option("", "--io-graph-marker-size", help="Disk IO dot size",
@@ -719,6 +779,8 @@
                       default=2, type="float")
     parser.add_option("-I", "--no-io-graph", help="Don't create an IO graph",
                       default=False, action="store_true")
+    parser.add_option("", "--only-io-graph", help="Create only IO graph",
+                      default=False, action="store_true");
     parser.add_option("-r", "--rolling-avg",
                   help="Rolling average for seeks and throughput (in seconds)",
                   default=None)
@@ -761,7 +823,7 @@
         rcParams['interactive'] = 'False'
     from pylab import *
 
-if not options.trace:
+if not options.trace and not options.file:
     parser.print_help()
     sys.exit(1)
 
@@ -788,29 +850,16 @@
 data = numpy.array([])
 runs = []
 must_sort = True
+devices_sector_max = {}
+device_translate = {}
 
 for x in options.trace:
-    devices_sector_max = {}
-    run = run_blkparse(x, converters)
-
-    device_translate = {}
-    total = 0
-    if len(devices_sector_max) > 1:
-        must_sort = True
-        for x in devices_sector_max:
-            device_translate[x] = total + devices_sector_max[x]
-            total += devices_sector_max[x]
-    shapeit(run)
-    if len(devices_sector_max) > 1:
-        for x in run:
-            sector = x[4]
-            dev = x[8]
-            x[4] = device_translate[dev] + sector
-        
-    sorted = sort_by_time(run)
-    run = sorted
+    run = process_input(x, 0)
+    runs.append(run)
+    data = numpy.append(data, run)
 
-    unshapeit(run)
+for x in options.file:
+    run = process_input(x, 1)
     runs.append(run)
     data = numpy.append(data, run)
 
@@ -910,6 +959,8 @@
 
 if options.no_io_graph:
     total_graphs = 2
+elif options.only_io_graph:
+    total_graphs = 1
 else:
     total_graphs = 3
 
@@ -922,76 +973,78 @@
 if options.title:
     options.title += "\n\n"
 
-# Throughput goes at the botoom
-a = subplot(total_graphs, 1, total_graphs)
-for i in xrange(len(runs)):
-    label = getlabel(i)
-    plot_throughput(a, None, runs[i], '-', label)
-
+# Prepare ticks
 # make sure the final second goes on the x axes
 ticks = list(arange(xmin, xmax, xmax/8))
 ticks.append(xmax)
 xticks = ticks
-a.set_xticks(ticks)
-a.set_yticklabels( [ "%d" % x for x in ticks ])
 if ticks[-1] < 4:
     xticklabels = [ "%.1f" % x for x in ticks ]
 else:
     xticklabels = [ "%d" % x for x in ticks ]
-a.set_xticklabels(xticklabels)
 
-# cut down the number of yticks to something more reasonable
-ticks = a.get_yticks()
-ticks = list(arange(0, ticks[-1] + ticks[-1]/4, ticks[-1]/4))
-a.set_yticks(ticks)
+if not options.only_io_graph:
+    # Throughput goes at the botoom
+    a = subplot(total_graphs, 1, total_graphs)
+    for i in xrange(len(runs)):
+        label = getlabel(i)
+        plot_throughput(a, None, runs[i], '-', label)
 
-if ticks[-1] < 4:
-    a.set_yticklabels( [ "%.1f" % x for x in ticks ])
-else:
-    a.set_yticklabels( [ "%d" % x for x in ticks ])
+    a.set_xticks(xticks)
+    a.set_yticklabels( [ "%d" % x for x in xticks ])
+    a.set_xticklabels(xticklabels)
 
-a.set_title('Throughput')
-a.set_ylabel('MB/s')
+    # cut down the number of yticks to something more reasonable
+    ticks = a.get_yticks()
+    ticks = list(arange(0, ticks[-1] + ticks[-1]/4, ticks[-1]/4))
+    a.set_yticks(ticks)
 
-# the bottom graph gets xticks, set it here
-a.set_xlabel('Time (seconds)')
-if options.label:
-    a.legend(loc=(1.01, 0.5), shadow=True, pad=0.5, numpoints=2,
-                  handletextsep = 0.005,
-                  labelsep = 0.01,
-                  prop=FontProperties(size='x-small') )
-
-# next is the seek count graph
-a = subplot(total_graphs, 1, total_graphs - 1)
-for i in xrange(len(runs)):
-    label = getlabel(i)
-    plot_seek_count(a, None, runs[i], '-', label)
-
-# cut down the number of yticks to something more reasonable
-ticks = a.get_yticks()
-ticks = list(arange(0, ticks[-1] + ticks[-1]/4, ticks[-1]/4))
-a.set_yticks(ticks)
-a.set_yticklabels( [ str(int(x)) for x in ticks ])
+    if ticks[-1] < 4:
+        a.set_yticklabels( [ "%.1f" % x for x in ticks ])
+    else:
+        a.set_yticklabels( [ "%d" % x for x in ticks ])
 
-if options.no_io_graph and options.title:
-    a.set_title(options.title + 'Seek Count')
-else:
-    a.set_title('Seek Count')
+    a.set_title('Throughput')
+    a.set_ylabel('MB/s')
+
+    # the bottom graph gets xticks, set it here
+    a.set_xlabel('Time (seconds)')
+    if options.label:
+        a.legend(loc=(1.01, 0.5), shadow=True, pad=0.5, numpoints=2,
+                      handletextsep = 0.005,
+                      labelsep = 0.01,
+                      prop=FontProperties(size='x-small') )
 
-a.set_ylabel('Seeks / sec')
-if options.label:
-    a.legend(loc=(1.01, 0.5), shadow=True, pad=0.5, numpoints=2,
-                  handletextsep = 0.005,
-                  labelsep = 0.01,
-                  prop=FontProperties(size='x-small') )
+    # next is the seek count graph
+    a = subplot(total_graphs, 1, total_graphs - 1)
+    for i in xrange(len(runs)):
+        label = getlabel(i)
+        plot_seek_count(a, None, runs[i], '-', label)
+
+    # cut down the number of yticks to something more reasonable
+    ticks = a.get_yticks()
+    ticks = list(arange(0, ticks[-1] + ticks[-1]/4, ticks[-1]/4))
+    a.set_yticks(ticks)
+    a.set_yticklabels( [ str(int(x)) for x in ticks ])
+
+    if options.no_io_graph and options.title:
+        a.set_title(options.title + 'Seek Count')
+    else:
+        a.set_title('Seek Count')
+
+    a.set_ylabel('Seeks / sec')
+    if options.label:
+        a.legend(loc=(1.01, 0.5), shadow=True, pad=0.5, numpoints=2,
+                      handletextsep = 0.005,
+                      labelsep = 0.01,
+                      prop=FontProperties(size='x-small') )
 
 # and the optional IO graph
 if not options.no_io_graph:
-    a = subplot(total_graphs, 1, total_graphs - 2)
+    a = subplot(total_graphs, 1, 1)
     for i in xrange(len(runs)):
         label = getlabel(i)
-        plot_data(a, 0, runs[i], options.io_graph_dots, label + " Read")
-        plot_data(a, 1, runs[i], options.io_graph_dots, label + " Write")
+        plot_data(a, runs[i], options.io_graph_dots, label)
 
     af = AnnoteFinder(axis=a)
     connect('button_press_event', af)
@@ -1008,17 +1061,27 @@
     ticks.append(yzoommax)
     a.set_yticks(ticks)
     a.set_yticklabels( [ str(int(x/2048)) for x in ticks ] )
-    a.legend(loc=(1.01, 0.5), shadow=True, pad=0.3, numpoints=1,
-                  handletextsep = 0.005,
-                  labelsep = 0.01,
-                  markerscale = 1.1,
-                  prop=FontProperties(size='x-small') )
+    if not options.only_io_graph:
+        a.legend(loc=(1.01, 0.5), shadow=True, pad=0.3, numpoints=1,
+                 handletextsep = 0.005,
+                 labelsep = 0.01,
+                 markerscale = 1.1,
+                 prop=FontProperties(size='x-small') )
+    else:
+        a.legend(loc=(0,-0.25), ncol=4, columnspacing=0.1,
+                 shadow=True, borderpad=0.3, numpoints=1,
+                 handletextpad = 0.005,
+                 labelspacing = 0.01,
+                 markerscale = 1.1,
+                 prop=FontProperties(size='x-small') )
+        subplots_adjust(bottom=0.2)
     a.set_ylim(yzoommin, yzoommax)
 
-# squeeze the graphs over to the left a bit to make room for the
-# legends
-#
-subplots_adjust(right = 0.8, hspace=0.3)
+if not options.only_io_graph:
+    # squeeze the graphs over to the left a bit to make room for the
+    # legends
+    #
+    subplots_adjust(right = 0.8, hspace=0.3)
 
 # finally, some global bits for each subplot
 for x in xrange(1, total_graphs + 1):
#!/usr/bin/env python

# Copyright (C) 2009 Novell.  All rights reserved.
#
# This program is free software; you can redistribute it and/or
# modify it under the terms of the GNU General Public
# License v2 as published by the Free Software Foundation.
# 
# This program is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
# General Public License for more details.
# 
# You should have received a copy of the GNU General Public
# License along with this program; if not, write to the
# Free Software Foundation, Inc., 59 Temple Place - Suite 330,
# Boston, MA 021110-1307, USA.
#
# You can use this script to produce files for seekwatcher with
# IO tagged by PID and / or command. Use option -m <command> to
# merge processes which have the same command name.
#
# Example:
# tag-by-process -t sda | seekwatcher -f - --only-io-graph

import sys, os, signal, time, commands, tempfile, signal
from optparse import OptionParser

def loaddata(fh):
    for i,line in enumerate(fh):
        if not line.startswith('Q'):
            continue
        row = line.split()
        if options.merge.count(row[10]) > 0:
            row[9] = row[10]
        else:
            row[9] = row[10] + "(" + row[9] + ")"
        for i in range(1,10):
            print row[i],
        print

def run_blkparse(trace):
    tracefiles = []
    seen = {}
    sys.stderr.write("run_blkparse on %s\n" % trace)
    if not os.path.exists(trace + "blktrace.0"):
        dirname = os.path.dirname(trace) or "."
        files = os.listdir(dirname)
        joinname = os.path.dirname(trace) or ""
        for x in files:
            x = os.path.join(joinname, x)
            if x.startswith(trace) and ".blktrace." in x:
                i = x.rindex('.blktrace.')
                cur = x[0:i]
                if cur not in seen:
                    tracefiles.append(x[0:i])
                    seen[cur] = 1
    else:
        tracefiles.append(trace)

    for x in tracefiles:
        sys.stderr.write("using tracefile %s\n" % x)
        p = os.popen('blkparse -q -i ' + x +
             ' -f "%a %d %M %m %S %N %s %5T.%9t %D %p %C\n"')
        cur = loaddata(p)
 
usage = "usage: %prog [options]"
parser = OptionParser(usage=usage)
parser.add_option("-t", "--trace", help="blktrace file", default=[],
                  action="append")
parser.add_option("-m", "--merge", help="merge commands with given names",
                  default=[], action="append")

(options,args) = parser.parse_args()

for x in options.trace:
    run = run_blkparse(x)