[20081120-21:57:43.481964097] PROCESSING COMMAND : 'clearprofilers' [20081120-21:57:43.725087185] PROCESSING COMMAND : 'useprofiler iostat 5' [20081120-21:57:43.830603317] Checking for sar... [20081120-21:57:43.832825998] found [20081120-21:57:43.966958536] PROCESSING COMMAND : 'useprofiler sar 5' [20081120-21:57:44.070736768] Checking for sar... [20081120-21:57:44.073036511] found [20081120-21:57:44.206769883] PROCESSING COMMAND : 'useprofiler mpstat 5' [20081120-21:57:44.312685003] Checking for sar... [20081120-21:57:44.314876635] found [20081120-21:57:44.478798862] PROCESSING COMMAND : 'useprofiler oprofile' [20081120-21:57:44.685058775] Checking for binutils-2.18 ... Already installed. [20081120-21:57:44.689019947] mv: cannot stat `lib64/*': No such file or directory [20081120-21:57:44.698178558] rmdir: lib64: No such file or directory [20081120-21:57:44.769364029] Checking for gettext-0.17 ... Already installed. [20081120-21:57:44.815544067] popt32-1.10.4 already installed. [20081120-21:57:44.830799168] popt64-1.10.4 already installed. [20081120-21:57:44.861077940] Checking for oprofile-0.9.4-autobench ... Already installed. [20081120-21:57:44.912798924] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081120-21:57:44.991492798] Daemon not running [20081120-21:57:45.014069428] Unloading oprofile module [20081120-21:57:45.242333426] Daemon not running [20081120-21:57:48.282384736] OPROFILE : using callgraph [5] [20081120-21:57:48.512369609] Daemon not running [20081120-21:57:48.514438565] Separate options: none [20081120-21:57:48.516550671] vmlinux file: /boot/vmlinux-2.6.27-frame-pointers [20081120-21:57:48.518769408] Image filter: none [20081120-21:57:48.520643449] Call-graph depth: 5 [20081120-21:57:48.657291691] PROCESSING COMMAND : 'useprofiler blktrace DEVICES=/dev/ffsbdev1' [20081120-21:57:48.936788208] PROCESSING COMMAND : 'umount /mnt/ffsb1 > /dev/null 2>&1' [20081120-21:57:49.010398899] PROCESSING COMMAND : 'set-sched noop' [20081120-21:57:49.391536727] PROCESSING COMMAND : 'mkresultdirs hks.austin.ibm.com benchmarks/results/btrfs/ffsb btrfs1 2008-11-20_2157 xfs-baseline' [20081120-21:57:49.635308244] Connecting to hks.austin.ibm.com... [20081120-21:57:49.637523092] Remote working directory: /opt [20081120-21:57:49.639477906] Remote working directory: /opt/benchmarks/results/btrfs/ffsb [20081120-21:57:49.641238034] Couldn't create directory: Failure [20081120-21:57:49.643157135] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1 [20081120-21:57:49.645347326] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs1 [20081120-21:57:49.647578340] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1/2008-11-20_2157 [20081120-21:57:49.649790326] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs1/2008-11-20_2157 [20081120-21:57:49.651808543] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1/2008-11-20_2157/xfs-baseline [20081120-21:57:49.719479315] PROCESSING COMMAND : 'mkfs.xfs -V 2>&1' [20081120-21:57:49.759480304] mkfs.xfs version 2.10.1 [20081120-21:57:49.853245536] PROCESSING COMMAND : 'mkfs.xfs -f /dev/ffsbdev1' [20081120-21:57:51.255561398] meta-data=/dev/ffsbdev1 isize=256 agcount=32, agsize=18327808 blks [20081120-21:57:51.257915550] = sectsz=512 attr=2 [20081120-21:57:51.260192471] data = bsize=4096 blocks=586489856, imaxpct=5 [20081120-21:57:51.262412514] = sunit=64 swidth=512 blks [20081120-21:57:51.264265533] naming =version 2 bsize=4096 ascii-ci=0 [20081120-21:57:51.266096294] log =internal log bsize=4096 blocks=32768, version=2 [20081120-21:57:51.268065427] = sectsz=512 sunit=64 blks, lazy-count=0 [20081120-21:57:51.270032297] realtime =none extsz=2097152 blocks=0, rtextents=0 [20081120-21:57:51.410651222] PROCESSING COMMAND : 'mkfs.xfs -f /dev/ffsbdev1' [20081120-21:57:52.743969585] meta-data=/dev/ffsbdev1 isize=256 agcount=32, agsize=18327808 blks [20081120-21:57:52.746028649] = sectsz=512 attr=2 [20081120-21:57:52.748323364] data = bsize=4096 blocks=586489856, imaxpct=5 [20081120-21:57:52.750569066] = sunit=64 swidth=512 blks [20081120-21:57:52.752508638] naming =version 2 bsize=4096 ascii-ci=0 [20081120-21:57:52.754322719] log =internal log bsize=4096 blocks=32768, version=2 [20081120-21:57:52.756047954] = sectsz=512 sunit=64 blks, lazy-count=0 [20081120-21:57:52.758004839] realtime =none extsz=2097152 blocks=0, rtextents=0 [20081120-21:57:52.796111520] PROCESSING COMMAND : 'mount -t xfs /dev/ffsbdev1 /mnt/ffsb1' [20081120-21:57:52.956396472] PROCESSING COMMAND : 'run large_file_creates__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/large_file_creates.ffsb num_threads=1' [20081120-21:57:53.000132802] new log requested [20081120-21:57:53.022753826] Running command ffsb [20081120-21:58:06.070671594] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/large_file_creates.ffsb [20081120-21:58:06.094212741] Importing argument : num_threads=1 [20081120-21:58:06.120563542] Found a xfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081120-21:58:06.209074233] Checking for sar... [20081120-21:58:06.211287478] found [20081120-21:58:06.267921474] Checking for sar... [20081120-21:58:06.270289103] found [20081120-21:58:06.326332717] Checking for sar... [20081120-21:58:06.328416913] found [20081120-21:58:06.456783246] Checking for binutils-2.18 ... Already installed. [20081120-21:58:06.461043137] mv: cannot stat `lib64/*': No such file or directory [20081120-21:58:06.464206445] rmdir: lib64: No such file or directory [20081120-21:58:06.523489176] Checking for gettext-0.17 ... Already installed. [20081120-21:58:06.564851430] popt32-1.10.4 already installed. [20081120-21:58:06.580697230] popt64-1.10.4 already installed. [20081120-21:58:06.611472244] Checking for oprofile-0.9.4-autobench ... Already installed. [20081120-21:58:06.663653610] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081120-21:58:06.744218977] Daemon not running [20081120-21:58:06.754719472] Unloading oprofile module [20081120-21:58:06.862630640] Daemon not running [20081120-21:58:07.091160835] OPROFILE : using callgraph [5] [20081120-21:58:07.322509091] Daemon not running [20081120-21:58:07.324579543] Separate options: none [20081120-21:58:07.326796659] vmlinux file: /boot/vmlinux-2.6.27-frame-pointers [20081120-21:58:07.328870243] Image filter: none [20081120-21:58:07.330808331] Call-graph depth: 5 [20081120-21:58:07.443288171] FFSB version 6.0-RC2 started [20081120-21:58:07.445491194] [20081120-21:58:07.447585802] benchmark time = 300 [20081120-21:58:07.449615843] ThreadGroup 0 [20081120-21:58:07.451794850] ================ [20081120-21:58:07.453891489] num_threads = 1 [20081120-21:58:07.456056715] [20081120-21:58:07.458063870] read_random = off [20081120-21:58:07.459894429] read_size = 0 (0B) [20081120-21:58:07.461821623] read_blocksize = 0 (0B) [20081120-21:58:07.463748411] read_skip = off [20081120-21:58:07.608423187] read_skipsize = 0 (0B) [20081120-21:58:07.610490149] [20081120-21:58:07.612454105] write_random = off [20081120-21:58:07.614423669] write_size = 0 (0B) [20081120-21:58:07.616147205] fsync_file = 0 [20081120-21:58:07.617946349] write_blocksize = 4096 (4KB) [20081120-21:58:07.619694533] wait time = 0 [20081120-21:58:07.621505404] [20081120-21:58:07.623214095] op weights [20081120-21:58:07.625002316] read = 0 (0.00%) [20081120-21:58:07.626733424] readall = 0 (0.00%) [20081120-21:58:07.628565994] write = 0 (0.00%) [20081120-21:58:07.630268489] create = 1 (100.00%) [20081120-21:58:07.632059168] append = 0 (0.00%) [20081120-21:58:07.633803039] delete = 0 (0.00%) [20081120-21:58:07.635631611] metaop = 0 (0.00%) [20081120-21:58:07.637366675] createdir = 0 (0.00%) [20081120-21:58:07.639155181] stat = 0 (0.00%) [20081120-21:58:07.640878045] writeall = 0 (0.00%) [20081120-21:58:07.642689699] writeall_fsync = 0 (0.00%) [20081120-21:58:07.644389967] open_close = 0 (0.00%) [20081120-21:58:07.646176097] write_fsync = 0 (0.00%) [20081120-21:58:07.647899307] create_fsync = 0 (0.00%) [20081120-21:58:07.649700436] append_fsync = 0 (0.00%) [20081120-21:58:07.651411615] [20081120-21:58:07.653222269] FileSystem /mnt/ffsb1 [20081120-21:58:07.654964579] ========== [20081120-21:58:07.656785596] num_dirs = 0 [20081120-21:58:07.658498599] starting files = 0 [20081120-21:58:07.660277395] [20081120-21:58:07.661989720] min file size = 1073741824 (1GB) [20081120-21:58:07.663785383] max file size = 1073741824 (1GB) [20081120-21:58:07.665504430] directio = off [20081120-21:58:07.667282008] alignedio = on [20081120-21:58:07.668997022] bufferedio = off [20081120-21:58:07.670778669] [20081120-21:58:07.672459381] aging is off [20081120-21:58:07.674227974] current utilization = 0.00% [20081120-21:58:07.675948605] [20081120-21:58:07.677740821] creating new fileset /mnt/ffsb1 [20081120-21:58:07.679455098] fs setup took 0 secs [20081120-21:58:07.905713766] Syncing()...0 sec [20081120-21:58:07.907883326] Starting Actual Benchmark At: Thu Nov 20 21:58:07 2008 [20081120-21:58:07.920928592] [20081120-22:03:14.213561468] Syncing()...1 sec [20081120-22:03:14.264201039] FFSB benchmark finished at: Thu Nov 20 22:03:13 2008 [20081120-22:03:14.267051964] [20081120-22:03:14.269864813] Results: [20081120-22:03:14.302001387] Benchmark took 306.01 sec [20081120-22:03:14.304661248] [20081120-22:03:14.307344330] Total Results [20081120-22:03:14.322344494] =============== [20081120-22:03:14.324460263] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081120-22:03:14.326841245] ======= ============ ========= ======= =========== ========== [20081120-22:03:14.329320760] create : 19660800 64249.33 100.000% 100.000% 251MB/sec [20081120-22:03:14.331828424] - [20081120-22:03:14.334296882] 64249.33 Transactions per Second [20081120-22:03:14.336467429] [20081120-22:03:14.338742669] Throughput Results [20081120-22:03:14.354003792] =================== [20081120-22:03:14.356399184] Write Throughput: 251MB/sec [20081120-22:03:14.358879088] [20081120-22:03:14.361345531] System Call Latency statistics in millisecs [20081120-22:03:14.363671554] ===== [20081120-22:03:14.366148697] Min Avg Max Total Calls [20081120-22:03:14.368614214] ======== ======== ======== ============ [20081120-22:03:14.370969157] [ open] 0.103000 0.160480 1.301000 75 [20081120-22:03:14.373146358] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081120-22:03:14.375409569] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081120-22:03:14.377548413] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081120-22:03:14.379774423] msec_range[3] 500.000000 - 1000.000000 : 0 [20081120-22:03:14.381911969] msec_range[4] 200.000000 - 500.000000 : 0 [20081120-22:03:14.384194934] msec_range[5] 100.000000 - 200.000000 : 0 [20081120-22:03:14.386486942] msec_range[6] 50.000000 - 100.000000 : 0 [20081120-22:03:14.389135781] msec_range[7] 20.000000 - 50.000000 : 0 [20081120-22:03:14.391387260] msec_range[8] 10.000000 - 20.000000 : 0 [20081120-22:03:14.393687203] msec_range[9] 5.000000 - 10.000000 : 0 [20081120-22:03:14.395942483] msec_range[10] 2.000000 - 5.000000 : 0 [20081120-22:03:14.398122779] msec_range[11] 1.000000 - 2.000000 : 1 [20081120-22:03:14.400828140] msec_range[12] 0.500000 - 1.000000 : 2 [20081120-22:03:14.403524298] msec_range[13] 0.200000 - 0.500000 : 0 [20081120-22:03:14.405832209] msec_range[14] 0.100000 - 0.200000 : 72 [20081120-22:03:14.417156109] msec_range[15] 0.050000 - 0.100000 : 0 [20081120-22:03:14.419590660] msec_range[16] 0.020000 - 0.050000 : 0 [20081120-22:03:14.421902205] msec_range[17] 0.010000 - 0.020000 : 0 [20081120-22:03:14.424445496] msec_range[18] 0.000000 - 0.010000 : 0 [20081120-22:03:14.427000074] [20081120-22:03:14.429440179] [ write] 0.009000 0.014862 182.013000 19660800 [20081120-22:03:14.431740703] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081120-22:03:14.434363008] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081120-22:03:14.436661624] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081120-22:03:14.439044842] msec_range[3] 500.000000 - 1000.000000 : 0 [20081120-22:03:14.441275383] msec_range[4] 200.000000 - 500.000000 : 0 [20081120-22:03:14.443724215] msec_range[5] 100.000000 - 200.000000 : 5 [20081120-22:03:14.446010862] msec_range[6] 50.000000 - 100.000000 : 9 [20081120-22:03:14.448342431] msec_range[7] 20.000000 - 50.000000 : 5 [20081120-22:03:14.450587840] msec_range[8] 10.000000 - 20.000000 : 10 [20081120-22:03:14.452868664] msec_range[9] 5.000000 - 10.000000 : 48 [20081120-22:03:14.454988051] msec_range[10] 2.000000 - 5.000000 : 20 [20081120-22:03:14.457168000] msec_range[11] 1.000000 - 2.000000 : 73 [20081120-22:03:14.459262514] msec_range[12] 0.500000 - 1.000000 : 2972 [20081120-22:03:14.461488574] msec_range[13] 0.200000 - 0.500000 : 183 [20081120-22:03:14.463644950] msec_range[14] 0.100000 - 0.200000 : 397 [20081120-22:03:14.465820554] msec_range[15] 0.050000 - 0.100000 : 25316 [20081120-22:03:14.468379820] msec_range[16] 0.020000 - 0.050000 : 2575038 [20081120-22:03:14.470710552] msec_range[17] 0.010000 - 0.020000 : 17056722 [20081120-22:03:14.473205952] msec_range[18] 0.000000 - 0.010000 : 2 [20081120-22:03:14.475609784] [20081120-22:03:14.477966984] [ close] 0.037000 0.045733 0.066000 75 [20081120-22:03:14.480120272] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081120-22:03:14.482431506] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081120-22:03:14.484735515] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081120-22:03:14.487103483] msec_range[3] 500.000000 - 1000.000000 : 0 [20081120-22:03:14.489325053] msec_range[4] 200.000000 - 500.000000 : 0 [20081120-22:03:14.491747339] msec_range[5] 100.000000 - 200.000000 : 0 [20081120-22:03:14.494111138] msec_range[6] 50.000000 - 100.000000 : 0 [20081120-22:03:14.496518462] msec_range[7] 20.000000 - 50.000000 : 0 [20081120-22:03:14.499015558] msec_range[8] 10.000000 - 20.000000 : 0 [20081120-22:03:14.501259525] msec_range[9] 5.000000 - 10.000000 : 0 [20081120-22:03:14.503475289] msec_range[10] 2.000000 - 5.000000 : 0 [20081120-22:03:14.505632581] msec_range[11] 1.000000 - 2.000000 : 0 [20081120-22:03:14.507910850] msec_range[12] 0.500000 - 1.000000 : 0 [20081120-22:03:14.510066803] msec_range[13] 0.200000 - 0.500000 : 0 [20081120-22:03:14.512251547] msec_range[14] 0.100000 - 0.200000 : 0 [20081120-22:03:14.514383198] msec_range[15] 0.050000 - 0.100000 : 11 [20081120-22:03:14.516595488] msec_range[16] 0.020000 - 0.050000 : 64 [20081120-22:03:14.518950332] msec_range[17] 0.010000 - 0.020000 : 0 [20081120-22:03:14.521155521] msec_range[18] 0.000000 - 0.010000 : 0 [20081120-22:03:14.523326560] [20081120-22:03:14.525709518] [20081120-22:03:14.527847106] [20081120-22:03:14.530043350] [20081120-22:03:14.532262047] 7.2% User Time [20081120-22:03:14.534569628] 91.0% System Time [20081120-22:03:14.536884810] 98.2% CPU Utilization [20081120-22:03:14.543848857] Profilers reporting [20081120-22:03:30.808907651] Profilers postprocessing [20081120-22:03:32.024677992] Stopping profiling. [20081120-22:03:32.029316038] Killing daemon. [20081120-22:03:34.477875741] Processing File : /autobench/logs/ffsb.large_file_creates__threads_0001.08-11-20_21.57.53/analysis/oprofile.001 [20081120-22:03:34.480320179] Processing File : /autobench/logs/ffsb.large_file_creates__threads_0001.08-11-20_21.57.53/analysis/oprofile-brief.001 [20081120-22:03:34.681571616] Processing File : mpstat.001 [20081120-22:03:34.683766436] Discovered mpstat_interval=[5] [20081120-22:03:35.349620826] Processing Directory : sar.breakout.001 [20081120-22:03:35.351891649] Discovered sar_interval=[5] [20081120-22:03:35.539254046] Processing File : iostat.001 [20081120-22:03:35.541419780] Discovered iostat_interval=[5] [20081120-22:03:44.335304739] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-11-20_2157/xfs-baseline' [20081120-22:03:54.404967387] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081120-22:03:55.899322500] PROCESSING COMMAND : 'mkfs.xfs -f /dev/ffsbdev1' [20081120-22:03:57.346215900] meta-data=/dev/ffsbdev1 isize=256 agcount=32, agsize=18327808 blks [20081120-22:03:57.348386618] = sectsz=512 attr=2 [20081120-22:03:57.350701448] data = bsize=4096 blocks=586489856, imaxpct=5 [20081120-22:03:57.352825330] = sunit=64 swidth=512 blks [20081120-22:03:57.354826964] naming =version 2 bsize=4096 ascii-ci=0 [20081120-22:03:57.356771664] log =internal log bsize=4096 blocks=32768, version=2 [20081120-22:03:57.358671021] = sectsz=512 sunit=64 blks, lazy-count=0 [20081120-22:03:57.360920321] realtime =none extsz=2097152 blocks=0, rtextents=0 [20081120-22:03:57.400396313] PROCESSING COMMAND : 'mount -t xfs /dev/ffsbdev1 /mnt/ffsb1' [20081120-22:03:57.557940788] PROCESSING COMMAND : 'run large_file_creates__threads_0016 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/large_file_creates.ffsb num_threads=16' [20081120-22:03:57.601709742] new log requested [20081120-22:03:57.623938120] Running command ffsb [20081120-22:04:09.781407925] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/large_file_creates.ffsb [20081120-22:04:09.796989150] Importing argument : num_threads=16 [20081120-22:04:09.822402340] Found a xfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081120-22:04:09.912798249] Checking for sar... [20081120-22:04:09.915179034] found [20081120-22:04:09.971503536] Checking for sar... [20081120-22:04:09.973613620] found [20081120-22:04:10.029837886] Checking for sar... [20081120-22:04:10.031933400] found [20081120-22:04:10.185914203] Checking for binutils-2.18 ... Already installed. [20081120-22:04:10.190400661] mv: cannot stat `lib64/*': No such file or directory [20081120-22:04:10.202987349] rmdir: lib64: No such file or directory [20081120-22:04:10.268334804] Checking for gettext-0.17 ... Already installed. [20081120-22:04:10.309373524] popt32-1.10.4 already installed. [20081120-22:04:10.324729923] popt64-1.10.4 already installed. [20081120-22:04:10.355882738] Checking for oprofile-0.9.4-autobench ... Already installed. [20081120-22:04:10.407985445] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081120-22:04:10.488689789] Daemon not running [20081120-22:04:10.506933525] Unloading oprofile module [20081120-22:04:10.731247406] Daemon not running [20081120-22:04:11.610871995] OPROFILE : using callgraph [5] [20081120-22:04:11.843877965] Daemon not running [20081120-22:04:11.846011917] Separate options: none [20081120-22:04:11.848063110] vmlinux file: /boot/vmlinux-2.6.27-frame-pointers [20081120-22:04:11.850143073] Image filter: none [20081120-22:04:11.852142228] Call-graph depth: 5 [20081120-22:04:11.969013592] FFSB version 6.0-RC2 started [20081120-22:04:11.970840932] [20081120-22:04:12.026310076] benchmark time = 300 [20081120-22:04:12.028310418] ThreadGroup 0 [20081120-22:04:12.030048819] ================ [20081120-22:04:12.032160740] num_threads = 16 [20081120-22:04:12.034296255] [20081120-22:04:12.036432462] read_random = off [20081120-22:04:12.038662093] read_size = 0 (0B) [20081120-22:04:12.040938482] read_blocksize = 0 (0B) [20081120-22:04:12.042962026] read_skip = off [20081120-22:04:12.044788202] read_skipsize = 0 (0B) [20081120-22:04:12.046717681] [20081120-22:04:12.048839077] write_random = off [20081120-22:04:12.050749570] write_size = 0 (0B) [20081120-22:04:12.052643626] fsync_file = 0 [20081120-22:04:12.054471676] write_blocksize = 4096 (4KB) [20081120-22:04:12.056322403] wait time = 0 [20081120-22:04:12.058074889] [20081120-22:04:12.059935293] op weights [20081120-22:04:12.061809927] read = 0 (0.00%) [20081120-22:04:12.063586620] readall = 0 (0.00%) [20081120-22:04:12.065464987] write = 0 (0.00%) [20081120-22:04:12.067262914] create = 1 (100.00%) [20081120-22:04:12.069084316] append = 0 (0.00%) [20081120-22:04:12.070827881] delete = 0 (0.00%) [20081120-22:04:12.072677322] metaop = 0 (0.00%) [20081120-22:04:12.074564161] createdir = 0 (0.00%) [20081120-22:04:12.076345945] stat = 0 (0.00%) [20081120-22:04:12.078220731] writeall = 0 (0.00%) [20081120-22:04:12.080015078] writeall_fsync = 0 (0.00%) [20081120-22:04:12.081839918] open_close = 0 (0.00%) [20081120-22:04:12.083553566] write_fsync = 0 (0.00%) [20081120-22:04:12.085437016] create_fsync = 0 (0.00%) [20081120-22:04:12.087298993] append_fsync = 0 (0.00%) [20081120-22:04:12.089066341] [20081120-22:04:12.090925764] FileSystem /mnt/ffsb1 [20081120-22:04:12.092725107] ========== [20081120-22:04:12.094549757] num_dirs = 0 [20081120-22:04:12.096307831] starting files = 0 [20081120-22:04:12.098175452] [20081120-22:04:12.100013918] min file size = 1073741824 (1GB) [20081120-22:04:12.101780787] max file size = 1073741824 (1GB) [20081120-22:04:12.103652977] directio = off [20081120-22:04:12.105440935] alignedio = on [20081120-22:04:12.107274826] bufferedio = off [20081120-22:04:12.109036566] [20081120-22:04:12.110891159] aging is off [20081120-22:04:12.112742153] current utilization = 0.00% [20081120-22:04:12.114501154] [20081120-22:04:12.116359349] creating new fileset /mnt/ffsb1 [20081120-22:04:12.118177106] fs setup took 0 secs [20081120-22:04:12.962060143] Syncing()...0 sec [20081120-22:04:12.964277994] Starting Actual Benchmark At: Thu Nov 20 22:04:12 2008 [20081120-22:04:12.977737096] [20081120-22:09:29.208983854] Syncing()...2 sec [20081120-22:09:29.250028698] FFSB benchmark finished at: Thu Nov 20 22:09:28 2008 [20081120-22:09:29.252939145] [20081120-22:09:29.255721661] Results: [20081120-22:09:29.300057853] Benchmark took 315.94 sec [20081120-22:09:29.302812070] [20081120-22:09:29.305550135] Total Results [20081120-22:09:29.320737719] =============== [20081120-22:09:29.322883739] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081120-22:09:29.325433458] ======= ============ ========= ======= =========== ========== [20081120-22:09:29.327748639] create : 44302336 140225.05 100.000% 100.000% 548MB/sec [20081120-22:09:29.329892925] - [20081120-22:09:29.332918495] 140225.05 Transactions per Second [20081120-22:09:29.335712236] [20081120-22:09:29.338288933] Throughput Results [20081120-22:09:29.353678485] =================== [20081120-22:09:29.355925097] Write Throughput: 548MB/sec [20081120-22:09:29.358153525] [20081120-22:09:29.360629235] System Call Latency statistics in millisecs [20081120-22:09:29.363079302] ===== [20081120-22:09:29.365355831] Min Avg Max Total Calls [20081120-22:09:29.367629332] ======== ======== ======== ============ [20081120-22:09:29.369781858] [ open] 0.122000 65.939438 1038.156982 169 [20081120-22:09:29.372027208] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081120-22:09:29.374235120] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081120-22:09:29.376428578] msec_range[2] 1000.000000 - 2000.000000 : 1 [20081120-22:09:29.378504234] msec_range[3] 500.000000 - 1000.000000 : 8 [20081120-22:09:29.380720006] msec_range[4] 200.000000 - 500.000000 : 8 [20081120-22:09:29.382789278] msec_range[5] 100.000000 - 200.000000 : 9 [20081120-22:09:29.385014822] msec_range[6] 50.000000 - 100.000000 : 6 [20081120-22:09:29.387233215] msec_range[7] 20.000000 - 50.000000 : 4 [20081120-22:09:29.389348492] msec_range[8] 10.000000 - 20.000000 : 5 [20081120-22:09:29.391549346] msec_range[9] 5.000000 - 10.000000 : 7 [20081120-22:09:29.393702789] msec_range[10] 2.000000 - 5.000000 : 0 [20081120-22:09:29.395971996] msec_range[11] 1.000000 - 2.000000 : 0 [20081120-22:09:29.398038633] msec_range[12] 0.500000 - 1.000000 : 7 [20081120-22:09:29.400383991] msec_range[13] 0.200000 - 0.500000 : 44 [20081120-22:09:29.402492048] msec_range[14] 0.100000 - 0.200000 : 70 [20081120-22:09:29.404663099] msec_range[15] 0.050000 - 0.100000 : 0 [20081120-22:09:29.406900496] msec_range[16] 0.020000 - 0.050000 : 0 [20081120-22:09:29.409010111] msec_range[17] 0.010000 - 0.020000 : 0 [20081120-22:09:29.411192725] msec_range[18] 0.000000 - 0.010000 : 0 [20081120-22:09:29.413304463] [20081120-22:09:29.415520673] [ write] 0.010000 0.109881 1543.863037 44302336 [20081120-22:09:29.417669868] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081120-22:09:29.419830749] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081120-22:09:29.421912646] msec_range[2] 1000.000000 - 2000.000000 : 68 [20081120-22:09:29.424069881] msec_range[3] 500.000000 - 1000.000000 : 390 [20081120-22:09:29.426156668] msec_range[4] 200.000000 - 500.000000 : 2454 [20081120-22:09:29.428337174] msec_range[5] 100.000000 - 200.000000 : 6148 [20081120-22:09:29.430408929] msec_range[6] 50.000000 - 100.000000 : 8930 [20081120-22:09:29.432553147] msec_range[7] 20.000000 - 50.000000 : 17928 [20081120-22:09:29.434630655] msec_range[8] 10.000000 - 20.000000 : 14091 [20081120-22:09:29.436767849] msec_range[9] 5.000000 - 10.000000 : 33632 [20081120-22:09:29.438844590] msec_range[10] 2.000000 - 5.000000 : 23468 [20081120-22:09:29.441096909] msec_range[11] 1.000000 - 2.000000 : 20366 [20081120-22:09:29.443154940] msec_range[12] 0.500000 - 1.000000 : 29952 [20081120-22:09:29.445314548] msec_range[13] 0.200000 - 0.500000 : 114835 [20081120-22:09:29.447388493] msec_range[14] 0.100000 - 0.200000 : 264903 [20081120-22:09:29.449816923] msec_range[15] 0.050000 - 0.100000 : 1987433 [20081120-22:09:29.452248959] msec_range[16] 0.020000 - 0.050000 : 24326095 [20081120-22:09:29.454448044] msec_range[17] 0.010000 - 0.020000 : 17451643 [20081120-22:09:29.457256933] msec_range[18] 0.000000 - 0.010000 : 0 [20081120-22:09:29.459696919] [20081120-22:09:29.462010742] [ close] 0.030000 0.053621 0.103000 169 [20081120-22:09:29.464120322] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081120-22:09:29.466513090] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081120-22:09:29.468706481] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081120-22:09:29.470880588] msec_range[3] 500.000000 - 1000.000000 : 0 [20081120-22:09:29.472976884] msec_range[4] 200.000000 - 500.000000 : 0 [20081120-22:09:29.475177837] msec_range[5] 100.000000 - 200.000000 : 0 [20081120-22:09:29.477293106] msec_range[6] 50.000000 - 100.000000 : 0 [20081120-22:09:29.479448645] msec_range[7] 20.000000 - 50.000000 : 0 [20081120-22:09:29.481524870] msec_range[8] 10.000000 - 20.000000 : 0 [20081120-22:09:29.483757331] msec_range[9] 5.000000 - 10.000000 : 0 [20081120-22:09:29.485910009] msec_range[10] 2.000000 - 5.000000 : 0 [20081120-22:09:29.488201857] msec_range[11] 1.000000 - 2.000000 : 0 [20081120-22:09:29.490337771] msec_range[12] 0.500000 - 1.000000 : 0 [20081120-22:09:29.492624991] msec_range[13] 0.200000 - 0.500000 : 0 [20081120-22:09:29.494759394] msec_range[14] 0.100000 - 0.200000 : 1 [20081120-22:09:29.496894228] msec_range[15] 0.050000 - 0.100000 : 100 [20081120-22:09:29.498988832] msec_range[16] 0.020000 - 0.050000 : 68 [20081120-22:09:29.501181828] msec_range[17] 0.010000 - 0.020000 : 0 [20081120-22:09:29.503272314] msec_range[18] 0.000000 - 0.010000 : 0 [20081120-22:09:29.505483566] [20081120-22:09:29.507982694] [20081120-22:09:29.510292932] [20081120-22:09:29.512611455] [20081120-22:09:29.515197140] 24.8% User Time [20081120-22:09:29.518340858] 713.8% System Time [20081120-22:09:29.520803421] 738.6% CPU Utilization [20081120-22:09:29.623040353] Profilers reporting [20081120-22:09:49.811569270] Profilers postprocessing [20081120-22:09:51.030306706] Stopping profiling. [20081120-22:09:51.035149872] Killing daemon. [20081120-22:09:53.722041437] Processing File : /autobench/logs/ffsb.large_file_creates__threads_0016.08-11-20_22.03.57/analysis/oprofile.001 [20081120-22:09:53.724342299] Processing File : /autobench/logs/ffsb.large_file_creates__threads_0016.08-11-20_22.03.57/analysis/oprofile-brief.001 [20081120-22:09:54.321536220] Processing File : mpstat.001 [20081120-22:09:54.323931502] Discovered mpstat_interval=[5] [20081120-22:09:55.081179185] Processing Directory : sar.breakout.001 [20081120-22:09:55.083452533] Discovered sar_interval=[5] [20081120-22:09:55.424195574] Processing File : iostat.001 [20081120-22:09:55.426380343] Discovered iostat_interval=[5] [20081120-22:10:13.204432115] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-11-20_2157/xfs-baseline' [20081120-22:14:07.083205634] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081120-22:14:08.271198315] PROCESSING COMMAND : 'mkfs.xfs -f /dev/ffsbdev1' [20081120-22:14:09.536485192] meta-data=/dev/ffsbdev1 isize=256 agcount=32, agsize=18327808 blks [20081120-22:14:09.540327573] = sectsz=512 attr=2 [20081120-22:14:09.543421604] data = bsize=4096 blocks=586489856, imaxpct=5 [20081120-22:14:09.545670820] = sunit=64 swidth=512 blks [20081120-22:14:09.547759871] naming =version 2 bsize=4096 ascii-ci=0 [20081120-22:14:09.550159129] log =internal log bsize=4096 blocks=32768, version=2 [20081120-22:14:09.552245475] = sectsz=512 sunit=64 blks, lazy-count=0 [20081120-22:14:09.554212118] realtime =none extsz=2097152 blocks=0, rtextents=0 [20081120-22:14:09.590191628] PROCESSING COMMAND : 'mount -t xfs /dev/ffsbdev1 /mnt/ffsb1' [20081120-22:14:09.734491748] PROCESSING COMMAND : 'run large_file_creates__threads_0128 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/large_file_creates.ffsb num_threads=128' [20081120-22:14:09.778210411] new log requested [20081120-22:14:09.801139174] Running command ffsb [20081120-22:14:21.933293327] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/large_file_creates.ffsb [20081120-22:14:21.948813336] Importing argument : num_threads=128 [20081120-22:14:21.974747510] Found a xfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081120-22:14:22.068975222] Checking for sar... [20081120-22:14:22.071221633] found [20081120-22:14:22.127409463] Checking for sar... [20081120-22:14:22.129808726] found [20081120-22:14:22.185602993] Checking for sar... [20081120-22:14:22.187830343] found [20081120-22:14:22.342529483] Checking for binutils-2.18 ... Already installed. [20081120-22:14:22.346962844] mv: cannot stat `lib64/*': No such file or directory [20081120-22:14:22.353716601] rmdir: lib64: No such file or directory [20081120-22:14:22.424907290] Checking for gettext-0.17 ... Already installed. [20081120-22:14:22.471748945] popt32-1.10.4 already installed. [20081120-22:14:22.487053619] popt64-1.10.4 already installed. [20081120-22:14:22.517883701] Checking for oprofile-0.9.4-autobench ... Already installed. [20081120-22:14:22.570428834] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081120-22:14:22.651131940] Daemon not running [20081120-22:14:22.669435112] Unloading oprofile module [20081120-22:14:22.902845167] Daemon not running [20081120-22:14:23.940953168] OPROFILE : using callgraph [5] [20081120-22:14:24.173192391] Daemon not running [20081120-22:14:24.175515082] Separate options: none [20081120-22:14:24.177677832] vmlinux file: /boot/vmlinux-2.6.27-frame-pointers [20081120-22:14:24.179585156] Image filter: none [20081120-22:14:24.181552270] Call-graph depth: 5 [20081120-22:14:24.291524049] FFSB version 6.0-RC2 started [20081120-22:14:24.293618775] [20081120-22:14:24.782529566] benchmark time = 300 [20081120-22:14:24.784642047] ThreadGroup 0 [20081120-22:14:24.786870964] ================ [20081120-22:14:24.788910943] num_threads = 128 [20081120-22:14:24.791138969] [20081120-22:14:24.793031956] read_random = off [20081120-22:14:24.795164088] read_size = 0 (0B) [20081120-22:14:24.797043190] read_blocksize = 0 (0B) [20081120-22:14:24.798993448] read_skip = off [20081120-22:14:24.800875139] read_skipsize = 0 (0B) [20081120-22:14:24.802658580] [20081120-22:14:24.804500321] write_random = off [20081120-22:14:24.806528568] write_size = 0 (0B) [20081120-22:14:24.808482582] fsync_file = 0 [20081120-22:14:24.810544982] write_blocksize = 4096 (4KB) [20081120-22:14:24.812443194] wait time = 0 [20081120-22:14:24.814328780] [20081120-22:14:24.816102791] op weights [20081120-22:14:24.817980532] read = 0 (0.00%) [20081120-22:14:24.819881176] readall = 0 (0.00%) [20081120-22:14:24.821703978] write = 0 (0.00%) [20081120-22:14:24.823571572] create = 1 (100.00%) [20081120-22:14:24.825356815] append = 0 (0.00%) [20081120-22:14:24.827197315] delete = 0 (0.00%) [20081120-22:14:24.828924025] metaop = 0 (0.00%) [20081120-22:14:24.830820847] createdir = 0 (0.00%) [20081120-22:14:24.832707656] stat = 0 (0.00%) [20081120-22:14:24.834505552] writeall = 0 (0.00%) [20081120-22:14:24.836363926] writeall_fsync = 0 (0.00%) [20081120-22:14:24.838139057] open_close = 0 (0.00%) [20081120-22:14:24.839976329] write_fsync = 0 (0.00%) [20081120-22:14:24.841747183] create_fsync = 0 (0.00%) [20081120-22:14:24.843614609] append_fsync = 0 (0.00%) [20081120-22:14:24.845513811] [20081120-22:14:24.847290875] FileSystem /mnt/ffsb1 [20081120-22:14:24.849136506] ========== [20081120-22:14:24.850900532] num_dirs = 0 [20081120-22:14:24.852737000] starting files = 0 [20081120-22:14:24.854502175] [20081120-22:14:24.856357644] min file size = 1073741824 (1GB) [20081120-22:14:24.858244538] max file size = 1073741824 (1GB) [20081120-22:14:24.860029867] directio = off [20081120-22:14:24.861895114] alignedio = on [20081120-22:14:24.863662177] bufferedio = off [20081120-22:14:24.865537898] [20081120-22:14:24.867281832] aging is off [20081120-22:14:24.869152593] current utilization = 0.00% [20081120-22:14:24.871043083] [20081120-22:14:24.872832584] creating new fileset /mnt/ffsb1 [20081120-22:14:24.874776278] fs setup took 0 secs [20081120-22:14:25.770658377] Syncing()...0 sec [20081120-22:14:25.777019035] Starting Actual Benchmark At: Thu Nov 20 22:14:25 2008 [20081120-22:14:25.790954836] [20081120-22:32:29.520833623] Syncing()...1 sec [20081120-22:32:29.595186568] FFSB benchmark finished at: Thu Nov 20 22:32:29 2008 [20081120-22:32:29.598253917] [20081120-22:32:29.601083999] Results: [20081120-22:32:29.707686227] Benchmark took 1083.42 sec [20081120-22:32:29.710347848] [20081120-22:32:29.712965032] Total Results [20081120-22:32:29.728053024] =============== [20081120-22:32:29.730451979] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081120-22:32:29.732912976] ======= ============ ========= ======= =========== ========== [20081120-22:32:29.735209952] create : 33554432 30970.75 100.000% 100.000% 121MB/sec [20081120-22:32:29.737414523] - [20081120-22:32:29.739751568] 30970.75 Transactions per Second [20081120-22:32:29.742061371] [20081120-22:32:29.744313686] Throughput Results [20081120-22:32:29.759258945] =================== [20081120-22:32:29.761658711] Write Throughput: 121MB/sec [20081120-22:32:29.763807082] [20081120-22:32:29.766012222] System Call Latency statistics in millisecs [20081120-22:32:29.768302554] ===== [20081120-22:32:29.770449728] Min Avg Max Total Calls [20081120-22:32:29.772711487] ======== ======== ======== ============ [20081120-22:32:29.775069265] [ open] 0.081000 366.111352 1902.996948 128 [20081120-22:32:29.777252504] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081120-22:32:29.779398923] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081120-22:32:29.781537191] msec_range[2] 1000.000000 - 2000.000000 : 11 [20081120-22:32:29.783787408] msec_range[3] 500.000000 - 1000.000000 : 30 [20081120-22:32:29.785887037] msec_range[4] 200.000000 - 500.000000 : 11 [20081120-22:32:29.787964430] msec_range[5] 100.000000 - 200.000000 : 5 [20081120-22:32:29.790395399] msec_range[6] 50.000000 - 100.000000 : 4 [20081120-22:32:29.792880286] msec_range[7] 20.000000 - 50.000000 : 30 [20081120-22:32:29.794884832] msec_range[8] 10.000000 - 20.000000 : 0 [20081120-22:32:29.796870489] msec_range[9] 5.000000 - 10.000000 : 3 [20081120-22:32:29.799109875] msec_range[10] 2.000000 - 5.000000 : 0 [20081120-22:32:29.801276382] msec_range[11] 1.000000 - 2.000000 : 2 [20081120-22:32:29.803487467] msec_range[12] 0.500000 - 1.000000 : 4 [20081120-22:32:29.805635651] msec_range[13] 0.200000 - 0.500000 : 11 [20081120-22:32:29.807851917] msec_range[14] 0.100000 - 0.200000 : 14 [20081120-22:32:29.810054092] msec_range[15] 0.050000 - 0.100000 : 3 [20081120-22:32:29.812176243] msec_range[16] 0.020000 - 0.050000 : 0 [20081120-22:32:29.814365345] msec_range[17] 0.010000 - 0.020000 : 0 [20081120-22:32:29.816566333] msec_range[18] 0.000000 - 0.010000 : 0 [20081120-22:32:29.818644720] [20081120-22:32:29.820841531] [ write] 0.010000 4.096346 4991.107910 33554432 [20081120-22:32:29.823107134] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081120-22:32:29.825279928] msec_range[1] 2000.000000 - 5000.000000 : 668 [20081120-22:32:29.827508370] msec_range[2] 1000.000000 - 2000.000000 : 15017 [20081120-22:32:29.829767381] msec_range[3] 500.000000 - 1000.000000 : 63483 [20081120-22:32:29.831864329] msec_range[4] 200.000000 - 500.000000 : 140630 [20081120-22:32:29.834047570] msec_range[5] 100.000000 - 200.000000 : 115670 [20081120-22:32:29.836262339] msec_range[6] 50.000000 - 100.000000 : 97396 [20081120-22:32:29.838353701] msec_range[7] 20.000000 - 50.000000 : 70979 [20081120-22:32:29.840688004] msec_range[8] 10.000000 - 20.000000 : 12634 [20081120-22:32:29.842818145] msec_range[9] 5.000000 - 10.000000 : 17670 [20081120-22:32:29.844823369] msec_range[10] 2.000000 - 5.000000 : 6667 [20081120-22:32:29.846848644] msec_range[11] 1.000000 - 2.000000 : 5076 [20081120-22:32:29.849110471] msec_range[12] 0.500000 - 1.000000 : 13385 [20081120-22:32:29.851294240] msec_range[13] 0.200000 - 0.500000 : 56177 [20081120-22:32:29.853409945] msec_range[14] 0.100000 - 0.200000 : 294128 [20081120-22:32:29.855427617] msec_range[15] 0.050000 - 0.100000 : 3325825 [20081120-22:32:29.857635304] msec_range[16] 0.020000 - 0.050000 : 27815683 [20081120-22:32:29.859705223] msec_range[17] 0.010000 - 0.020000 : 1503344 [20081120-22:32:29.861975460] msec_range[18] 0.000000 - 0.010000 : 0 [20081120-22:32:29.864550277] [20081120-22:32:29.868545985] [ close] 0.022000 0.062047 1.320000 128 [20081120-22:32:29.871175500] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081120-22:32:29.873807920] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081120-22:32:29.876100800] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081120-22:32:29.878658289] msec_range[3] 500.000000 - 1000.000000 : 0 [20081120-22:32:29.881006083] msec_range[4] 200.000000 - 500.000000 : 0 [20081120-22:32:29.883329686] msec_range[5] 100.000000 - 200.000000 : 0 [20081120-22:32:29.885712884] msec_range[6] 50.000000 - 100.000000 : 0 [20081120-22:32:29.887914296] msec_range[7] 20.000000 - 50.000000 : 0 [20081120-22:32:29.890038497] msec_range[8] 10.000000 - 20.000000 : 0 [20081120-22:32:29.892027526] msec_range[9] 5.000000 - 10.000000 : 0 [20081120-22:32:29.894602332] msec_range[10] 2.000000 - 5.000000 : 0 [20081120-22:32:29.897112979] msec_range[11] 1.000000 - 2.000000 : 1 [20081120-22:32:29.899865695] msec_range[12] 0.500000 - 1.000000 : 0 [20081120-22:32:29.902415465] msec_range[13] 0.200000 - 0.500000 : 0 [20081120-22:32:29.904845296] msec_range[14] 0.100000 - 0.200000 : 1 [20081120-22:32:29.906889384] msec_range[15] 0.050000 - 0.100000 : 76 [20081120-22:32:29.908921877] msec_range[16] 0.020000 - 0.050000 : 50 [20081120-22:32:29.911233054] msec_range[17] 0.010000 - 0.020000 : 0 [20081120-22:32:29.913452713] msec_range[18] 0.000000 - 0.010000 : 0 [20081120-22:32:29.915460155] [20081120-22:32:29.917605298] [20081120-22:32:29.920270597] [20081120-22:32:29.922753926] [20081120-22:32:29.925065496] 7.4% User Time [20081120-22:32:29.927355521] 1495.7% System Time [20081120-22:32:29.929642008] 1503.1% CPU Utilization [20081120-22:32:29.976430465] Profilers reporting [20081120-22:32:47.324619182] Profilers postprocessing [20081120-22:32:48.539344684] Stopping profiling. [20081120-22:32:48.544435609] Killing daemon. [20081120-22:32:50.980972018] Processing File : /autobench/logs/ffsb.large_file_creates__threads_0128.08-11-20_22.14.09/analysis/oprofile.001 [20081120-22:32:50.983259801] Processing File : /autobench/logs/ffsb.large_file_creates__threads_0128.08-11-20_22.14.09/analysis/oprofile-brief.001 [20081120-22:32:51.313202960] Processing File : mpstat.001 [20081120-22:32:51.315394385] Discovered mpstat_interval=[5] [20081120-22:32:52.620673700] Processing Directory : sar.breakout.001 [20081120-22:32:52.622873223] Discovered sar_interval=[5] [20081120-22:32:52.925374873] Processing File : iostat.001 [20081120-22:32:52.927656759] Discovered iostat_interval=[5] [20081120-22:33:02.716056815] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-11-20_2157/xfs-baseline'