[20081021-19:26:46.309796509] PROCESSING COMMAND : 'clearprofilers' [20081021-19:26:46.561397400] PROCESSING COMMAND : 'useprofiler iostat 5' [20081021-19:26:46.663393520] Checking for sar... [20081021-19:26:46.665759881] found [20081021-19:26:46.799706126] PROCESSING COMMAND : 'useprofiler sar 5' [20081021-19:26:46.902450645] Checking for sar... [20081021-19:26:46.905455184] found [20081021-19:26:47.038657399] PROCESSING COMMAND : 'useprofiler mpstat 5' [20081021-19:26:47.141108298] Checking for sar... [20081021-19:26:47.143227700] found [20081021-19:26:47.275229063] PROCESSING COMMAND : 'useprofiler oprofile' [20081021-19:26:47.414894034] Checking for gettext... [20081021-19:26:47.426880295] found [20081021-19:26:47.428960968] Checking for libiberty... [20081021-19:26:47.446423061] found [20081021-19:26:47.448144840] Checking for popt... [20081021-19:26:47.456003776] found [20081021-19:26:47.464217428] Checking for popt64... [20081021-19:26:47.466087888] found [20081021-19:26:47.468018635] Checking for oprofile... [20081021-19:26:47.469995196] found [20081021-19:26:47.518385272] opcontrol: oprofile 0.9.3 compiled on Sep 25 2008 09:52:31 [20081021-19:26:47.594422446] Daemon not running [20081021-19:26:47.611050892] Unloading oprofile module [20081021-19:26:47.821742447] Daemon not running [20081021-19:26:48.207979315] Daemon not running [20081021-19:26:48.210070288] Separate options: none [20081021-19:26:48.212049271] vmlinux file: /boot/vmlinux-2.6.27-rc7 [20081021-19:26:48.214188188] Image filter: none [20081021-19:26:48.216021798] Call-graph depth: 0 [20081021-19:26:48.354369092] PROCESSING COMMAND : 'useprofiler blktrace DEVICES=/dev/ffsbdev1' [20081021-19:26:48.631225712] PROCESSING COMMAND : 'umount /mnt/ffsb1 > /dev/null 2>&1' [20081021-19:26:48.703545360] PROCESSING COMMAND : 'set-sched noop' [20081021-19:26:49.077195727] PROCESSING COMMAND : 'mkresultdirs hks.austin.ibm.com benchmarks/results/btrfs/ffsb btrfs1 2008-10-21_1926 btrfs-nodatacow-nodatasum' [20081021-19:26:49.313518108] Connecting to hks.austin.ibm.com... [20081021-19:26:49.315606101] Remote working directory: /opt [20081021-19:26:49.317866918] Remote working directory: /opt/benchmarks/results/btrfs/ffsb [20081021-19:26:49.319861352] Couldn't create directory: Failure [20081021-19:26:49.321565417] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1 [20081021-19:26:49.323612455] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs1 [20081021-19:26:49.325652044] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1/2008-10-21_1926 [20081021-19:26:49.327569300] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs1/2008-10-21_1926 [20081021-19:26:49.329600789] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1/2008-10-21_1926/btrfs-nodatacow-nodatasum [20081021-19:26:49.397185768] PROCESSING COMMAND : 'mkfs.btrfs -V > /autobench/logs//mkfs.version 2>&1' [20081021-19:26:49.529193230] PROCESSING COMMAND : 'mkfs.btrfs /dev/ffsbdev1' [20081021-19:26:49.567415888] fs created label (null) on /dev/ffsbdev1 [20081021-19:26:49.571560977] nodesize 4096 leafsize 4096 sectorsize 4096 size 2.18TB [20081021-19:26:49.573593736] Btrfs v0.16-11-gb431f25 [20081021-19:26:49.733834898] PROCESSING COMMAND : 'mount -t btrfs -o nodatacow,nodatasum /dev/ffsbdev1 /mnt/ffsb1' [20081021-19:26:49.842992635] PROCESSING COMMAND : 'run sequential_reads__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb num_threads=1' [20081021-19:26:49.895090233] new log requested [20081021-19:26:49.917202431] Running command ffsb [20081021-19:27:00.767556476] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb [20081021-19:27:00.774940913] Importing argument : num_threads=1 [20081021-19:27:00.792117797] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081021-19:27:00.878732159] Checking for sar... [20081021-19:27:00.881092472] found [20081021-19:27:00.936988417] Checking for sar... [20081021-19:27:00.939004613] found [20081021-19:27:00.993777342] Checking for sar... [20081021-19:27:00.995920083] found [20081021-19:27:01.068908150] Checking for gettext... [20081021-19:27:01.071078451] found [20081021-19:27:01.073042698] Checking for libiberty... [20081021-19:27:01.075206497] found [20081021-19:27:01.077291347] Checking for popt... [20081021-19:27:01.079226059] found [20081021-19:27:01.081266370] Checking for popt64... [20081021-19:27:01.083160282] found [20081021-19:27:01.085041946] Checking for oprofile... [20081021-19:27:01.086960509] found [20081021-19:27:01.133362727] opcontrol: oprofile 0.9.3 compiled on Sep 25 2008 09:52:31 [20081021-19:27:01.210131177] Daemon not running [20081021-19:27:01.220518561] Unloading oprofile module [20081021-19:27:01.319507807] Daemon not running [20081021-19:27:01.584224930] Daemon not running [20081021-19:27:01.586372453] Separate options: none [20081021-19:27:01.588416402] vmlinux file: /boot/vmlinux-2.6.27-rc7 [20081021-19:27:01.590427238] Image filter: none [20081021-19:27:01.592365886] Call-graph depth: 0 [20081021-19:27:01.711645125] FFSB version 5.2.1 started [20081021-19:27:01.713789299] [20081021-19:27:01.715867826] benchmark time = 300 [20081021-19:27:01.717798722] ThreadGroup 0 [20081021-19:27:01.719956548] ================ [20081021-19:27:01.721892428] num_threads = 1 [20081021-19:27:01.723629410] [20081021-19:27:01.725559401] read_random = off [20081021-19:27:01.727412242] read_size = 104857600 (100MB) [20081021-19:27:01.729444044] read_blocksize = 4096 (4KB) [20081021-19:27:01.731257036] read_skip = off [20081021-19:27:01.733111562] read_skipsize = 0 (0B) [20081021-19:27:01.734930229] [20081021-19:27:01.736633497] write_random = off [20081021-19:27:01.738466440] write_size = 0 (0B) [20081021-19:27:01.740211762] fsync_file = 0 [20081021-19:27:01.742053696] write_blocksize = 0 (0B) [20081021-19:27:01.743856495] wait time = 0 [20081021-19:27:01.745563064] [20081021-19:27:01.747251623] op weights [20081021-19:27:01.749002538] read = 1 (100.00%) [20081021-19:27:01.750874534] readall = 0 (0.00%) [20081021-19:27:01.752708003] write = 0 (0.00%) [20081021-19:27:01.754431756] create = 0 (0.00%) [20081021-19:27:01.756270981] append = 0 (0.00%) [20081021-19:27:01.758008412] delete = 0 (0.00%) [20081021-19:27:01.759789064] metaop = 0 (0.00%) [20081021-19:27:01.761497355] createdir = 0 (0.00%) [20081021-19:27:01.763333614] stat = 0 (0.00%) [20081021-19:27:01.765151622] writeall = 0 (0.00%) [20081021-19:27:01.766864361] writeall_fsync = 0 (0.00%) [20081021-19:27:01.768657521] open_close = 0 (0.00%) [20081021-19:27:01.770381989] [20081021-19:27:01.772141587] FileSystem /mnt/ffsb1 [20081021-19:27:01.773835587] ========== [20081021-19:27:01.775636142] num_dirs = 0 [20081021-19:27:01.777443118] starting files = 1024 [20081021-19:27:01.779145603] [20081021-19:27:01.780950107] min file size = 104857600 (100MB) [20081021-19:27:01.782656484] max file size = 104857600 (100MB) [20081021-19:27:01.784428576] directio = off [20081021-19:27:01.786145208] alignedio = on [20081021-19:27:01.787967888] bufferedio = off [20081021-19:27:01.789772078] [20081021-19:27:01.791499663] aging is off [20081021-19:27:01.793313366] current utilization = 0.00% [20081021-19:27:01.795040338] [20081021-19:27:01.796797755] opendir: No such file or directory [20081021-19:27:01.798491950] checking existing fs: /mnt/ffsb1 [20081021-19:27:01.800312394] recreating new fileset [20081021-19:34:48.940602941] fs setup took 467 secs [20081021-19:34:49.188360770] Syncing()...0 sec [20081021-19:34:49.190834406] Starting Actual Benchmark At: Tue Oct 21 19:34:49 2008 [20081021-19:34:49.240974389] [20081021-19:39:51.481386600] Syncing()...0 sec [20081021-19:39:51.524888225] FFSB benchmark finished at: Tue Oct 21 19:39:51 2008 [20081021-19:39:51.527296715] [20081021-19:39:51.538400106] Results: [20081021-19:39:51.601298116] Benchmark took 302.18 sec [20081021-19:39:51.603915969] [20081021-19:39:51.606242486] Total Results [20081021-19:39:51.620515352] =============== [20081021-19:39:51.622948863] Throughput: 19569.90 reads/sec -> 76.4MB/sec [20081021-19:39:51.625116364] 19569.90 Transactions per Second [20081021-19:39:51.627225491] [20081021-19:39:51.629328981] System Call Latency statistics in millisecs [20081021-19:39:51.631317293] ===== [20081021-19:39:51.633365275] Min Avg Max Total Calls [20081021-19:39:51.635283174] ======== ======== ======== ============ [20081021-19:39:51.637309830] [ open] 0.018000 0.290784 20.190001 231 [20081021-19:39:51.639564217] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-19:39:51.641662283] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-19:39:51.643877168] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-19:39:51.646316236] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-19:39:51.648416516] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-19:39:51.650536104] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-19:39:51.652469059] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-19:39:51.654413447] msec_range[7] 20.000000 - 50.000000 : 1 [20081021-19:39:51.656305914] msec_range[8] 10.000000 - 20.000000 : 1 [20081021-19:39:51.658270501] msec_range[9] 5.000000 - 10.000000 : 3 [20081021-19:39:51.660219354] msec_range[10] 2.000000 - 5.000000 : 3 [20081021-19:39:51.662316605] msec_range[11] 1.000000 - 2.000000 : 0 [20081021-19:39:51.664237561] msec_range[12] 0.500000 - 1.000000 : 0 [20081021-19:39:51.666334945] msec_range[13] 0.200000 - 0.500000 : 0 [20081021-19:39:51.668353755] msec_range[14] 0.100000 - 0.200000 : 0 [20081021-19:39:51.670288218] msec_range[15] 0.050000 - 0.100000 : 1 [20081021-19:39:51.672155517] msec_range[16] 0.020000 - 0.050000 : 143 [20081021-19:39:51.674082747] msec_range[17] 0.010000 - 0.020000 : 79 [20081021-19:39:51.675942474] msec_range[18] 0.000000 - 0.010000 : 0 [20081021-19:39:51.677880717] [20081021-19:39:51.679719638] [ read] 0.004000 0.050703 270.346985 5913600 [20081021-19:39:51.681640229] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-19:39:51.683623765] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-19:39:51.685693102] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-19:39:51.687860121] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-19:39:51.689877012] msec_range[4] 200.000000 - 500.000000 : 1 [20081021-19:39:51.691978645] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-19:39:51.693885359] msec_range[6] 50.000000 - 100.000000 : 1 [20081021-19:39:51.695919581] msec_range[7] 20.000000 - 50.000000 : 5 [20081021-19:39:51.697849444] msec_range[8] 10.000000 - 20.000000 : 44 [20081021-19:39:51.699888520] msec_range[9] 5.000000 - 10.000000 : 10099 [20081021-19:39:51.702618317] msec_range[10] 2.000000 - 5.000000 : 32417 [20081021-19:39:51.704914937] msec_range[11] 1.000000 - 2.000000 : 56138 [20081021-19:39:51.707127950] msec_range[12] 0.500000 - 1.000000 : 37651 [20081021-19:39:51.709406726] msec_range[13] 0.200000 - 0.500000 : 7773 [20081021-19:39:51.711678835] msec_range[14] 0.100000 - 0.200000 : 33854 [20081021-19:39:51.713682038] msec_range[15] 0.050000 - 0.100000 : 50501 [20081021-19:39:51.715836893] msec_range[16] 0.020000 - 0.050000 : 1344 [20081021-19:39:51.717873826] msec_range[17] 0.010000 - 0.020000 : 38574 [20081021-19:39:51.719861879] msec_range[18] 0.000000 - 0.010000 : 5645198 [20081021-19:39:51.721788090] [20081021-19:39:51.723926383] [ close] 0.005000 0.005788 0.009000 231 [20081021-19:39:51.725930867] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-19:39:51.728106385] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-19:39:51.730772354] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-19:39:51.733049058] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-19:39:51.735401666] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-19:39:51.737400752] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-19:39:51.739545088] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-19:39:51.741633980] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-19:39:51.743692394] msec_range[8] 10.000000 - 20.000000 : 0 [20081021-19:39:51.745720976] msec_range[9] 5.000000 - 10.000000 : 0 [20081021-19:39:51.747880848] msec_range[10] 2.000000 - 5.000000 : 0 [20081021-19:39:51.749857322] msec_range[11] 1.000000 - 2.000000 : 0 [20081021-19:39:51.751938560] msec_range[12] 0.500000 - 1.000000 : 0 [20081021-19:39:51.753857288] msec_range[13] 0.200000 - 0.500000 : 0 [20081021-19:39:51.755885779] msec_range[14] 0.100000 - 0.200000 : 0 [20081021-19:39:51.757873756] msec_range[15] 0.050000 - 0.100000 : 0 [20081021-19:39:51.759838087] msec_range[16] 0.020000 - 0.050000 : 0 [20081021-19:39:51.761717145] msec_range[17] 0.010000 - 0.020000 : 0 [20081021-19:39:51.763720337] msec_range[18] 0.000000 - 0.010000 : 231 [20081021-19:39:51.765637211] [20081021-19:39:51.767630229] [20081021-19:39:51.769493206] [20081021-19:39:51.771537413] [20081021-19:39:51.773833371] 1.2% User Time [20081021-19:39:51.776044403] 15.3% System Time [20081021-19:39:51.778390393] 16.6% CPU Utilization [20081021-19:39:51.780419751] Profilers reporting [20081021-19:39:54.476873024] Profilers postprocessing [20081021-19:39:55.712543987] Stopping profiling. [20081021-19:39:55.717231102] Killing daemon. [20081021-19:39:56.159973091] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0001.08-10-21_19.26.49/analysis/oprofile.001 [20081021-19:39:56.162296700] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0001.08-10-21_19.26.49/analysis/oprofile-brief.001 [20081021-19:39:56.348487186] Processing File : mpstat.001 [20081021-19:39:56.350449536] Discovered mpstat_interval=[5] [20081021-19:39:56.917798860] Processing Directory : sar.breakout.001 [20081021-19:39:56.920055224] Discovered sar_interval=[5] [20081021-19:39:57.068141016] Processing File : iostat.001 [20081021-19:39:57.070327690] Discovered iostat_interval=[5] [20081021-19:40:01.758680276] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-10-21_1926/btrfs-nodatacow-nodatasum' [20081021-19:40:11.081513345] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081021-19:40:13.117751242] PROCESSING COMMAND : 'mount -t btrfs -o nodatacow,nodatasum /dev/ffsbdev1 /mnt/ffsb1' [20081021-19:40:13.259356759] PROCESSING COMMAND : 'run sequential_reads__threads_0016 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb num_threads=16' [20081021-19:40:13.315772141] new log requested [20081021-19:40:13.338242240] Running command ffsb [20081021-19:40:24.113220638] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb [20081021-19:40:24.122109516] Importing argument : num_threads=16 [20081021-19:40:24.139376538] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081021-19:40:24.238376534] Checking for sar... [20081021-19:40:24.240577136] found [20081021-19:40:24.296232700] Checking for sar... [20081021-19:40:24.298389435] found [20081021-19:40:24.353700573] Checking for sar... [20081021-19:40:24.355852987] found [20081021-19:40:24.438525631] Checking for gettext... [20081021-19:40:24.447514629] found [20081021-19:40:24.449596060] Checking for libiberty... [20081021-19:40:24.469950067] found [20081021-19:40:24.471660820] Checking for popt... [20081021-19:40:24.479656863] found [20081021-19:40:24.488277242] Checking for popt64... [20081021-19:40:24.490193246] found [20081021-19:40:24.492169543] Checking for oprofile... [20081021-19:40:24.494160744] found [20081021-19:40:24.542767264] opcontrol: oprofile 0.9.3 compiled on Sep 25 2008 09:52:31 [20081021-19:40:24.621383102] Daemon not running [20081021-19:40:24.642638786] Unloading oprofile module [20081021-19:40:24.911609880] Daemon not running [20081021-19:40:25.313683791] Daemon not running [20081021-19:40:25.315922953] Separate options: none [20081021-19:40:25.317906781] vmlinux file: /boot/vmlinux-2.6.27-rc7 [20081021-19:40:25.319845704] Image filter: none [20081021-19:40:25.321570387] Call-graph depth: 0 [20081021-19:40:25.432707637] FFSB version 5.2.1 started [20081021-19:40:25.434907825] [20081021-19:40:25.491047989] benchmark time = 300 [20081021-19:40:25.492962462] ThreadGroup 0 [20081021-19:40:25.494728083] ================ [20081021-19:40:25.496335772] num_threads = 16 [20081021-19:40:25.498500507] [20081021-19:40:25.500336003] read_random = off [20081021-19:40:25.502102303] read_size = 104857600 (100MB) [20081021-19:40:25.503765260] read_blocksize = 4096 (4KB) [20081021-19:40:25.505719720] read_skip = off [20081021-19:40:25.507912785] read_skipsize = 0 (0B) [20081021-19:40:25.509927068] [20081021-19:40:25.512051494] write_random = off [20081021-19:40:25.514211211] write_size = 0 (0B) [20081021-19:40:25.516006499] fsync_file = 0 [20081021-19:40:25.517717165] write_blocksize = 0 (0B) [20081021-19:40:25.519459356] wait time = 0 [20081021-19:40:25.521239864] [20081021-19:40:25.523031813] op weights [20081021-19:40:25.524727743] read = 1 (100.00%) [20081021-19:40:25.526822909] readall = 0 (0.00%) [20081021-19:40:25.528686087] write = 0 (0.00%) [20081021-19:40:25.530377413] create = 0 (0.00%) [20081021-19:40:25.532086524] append = 0 (0.00%) [20081021-19:40:25.533889093] delete = 0 (0.00%) [20081021-19:40:25.535620434] metaop = 0 (0.00%) [20081021-19:40:25.537377652] createdir = 0 (0.00%) [20081021-19:40:25.539048391] stat = 0 (0.00%) [20081021-19:40:25.540804827] writeall = 0 (0.00%) [20081021-19:40:25.542645987] writeall_fsync = 0 (0.00%) [20081021-19:40:25.544326300] open_close = 0 (0.00%) [20081021-19:40:25.546178575] [20081021-19:40:25.547928657] FileSystem /mnt/ffsb1 [20081021-19:40:25.549706555] ========== [20081021-19:40:25.551365891] num_dirs = 0 [20081021-19:40:25.553206977] starting files = 1024 [20081021-19:40:25.555025714] [20081021-19:40:25.556749984] min file size = 104857600 (100MB) [20081021-19:40:25.558576921] max file size = 104857600 (100MB) [20081021-19:40:25.560350713] directio = off [20081021-19:40:25.562007731] alignedio = on [20081021-19:40:25.563853559] bufferedio = off [20081021-19:40:25.565639033] [20081021-19:40:25.567402504] aging is off [20081021-19:40:25.569062418] current utilization = 4.47% [20081021-19:40:25.570825204] [20081021-19:40:25.572487309] checking existing fs: /mnt/ffsb1 [20081021-19:40:25.596546060] fs setup took 0 secs [20081021-19:40:25.994526037] Syncing()...0 sec [20081021-19:40:25.996579990] Starting Actual Benchmark At: Tue Oct 21 19:40:25 2008 [20081021-19:40:26.010159379] [20081021-19:45:31.806872850] Syncing()...2 sec [20081021-19:45:31.851757172] FFSB benchmark finished at: Tue Oct 21 19:45:31 2008 [20081021-19:45:31.854322079] [20081021-19:45:31.856735804] Results: [20081021-19:45:31.920457228] Benchmark took 305.57 sec [20081021-19:45:31.922301178] [20081021-19:45:31.924508139] Total Results [20081021-19:45:31.938357366] =============== [20081021-19:45:31.940541100] Throughput: 117873.91 reads/sec -> 460MB/sec [20081021-19:45:31.942757757] 117873.91 Transactions per Second [20081021-19:45:31.945097658] [20081021-19:45:31.947379352] System Call Latency statistics in millisecs [20081021-19:45:31.949582644] ===== [20081021-19:45:31.951531151] Min Avg Max Total Calls [20081021-19:45:31.965769096] ======== ======== ======== ============ [20081021-19:45:31.968188113] [ open] 0.006000 0.281221 18.306999 1407 [20081021-19:45:31.970405870] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-19:45:31.972669075] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-19:45:31.974728894] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-19:45:31.976726294] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-19:45:31.978690208] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-19:45:31.980683093] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-19:45:31.982591996] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-19:45:31.984574125] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-19:45:31.986479570] msec_range[8] 10.000000 - 20.000000 : 6 [20081021-19:45:31.988432403] msec_range[9] 5.000000 - 10.000000 : 33 [20081021-19:45:31.990337982] msec_range[10] 2.000000 - 5.000000 : 11 [20081021-19:45:31.992346564] msec_range[11] 1.000000 - 2.000000 : 1 [20081021-19:45:31.994195446] msec_range[12] 0.500000 - 1.000000 : 0 [20081021-19:45:31.996191335] msec_range[13] 0.200000 - 0.500000 : 0 [20081021-19:45:31.998132648] msec_range[14] 0.100000 - 0.200000 : 1 [20081021-19:45:31.999992844] msec_range[15] 0.050000 - 0.100000 : 165 [20081021-19:45:32.001969096] msec_range[16] 0.020000 - 0.050000 : 1147 [20081021-19:45:32.003933103] msec_range[17] 0.010000 - 0.020000 : 32 [20081021-19:45:32.005808947] msec_range[18] 0.000000 - 0.010000 : 11 [20081021-19:45:32.007728724] [20081021-19:45:32.009578718] [ read] 0.001000 0.133920 95.587997 36019200 [20081021-19:45:32.011579129] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-19:45:32.013463128] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-19:45:32.015402817] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-19:45:32.017289527] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-19:45:32.019230606] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-19:45:32.021112826] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-19:45:32.023024500] msec_range[6] 50.000000 - 100.000000 : 28 [20081021-19:45:32.024885046] msec_range[7] 20.000000 - 50.000000 : 3729 [20081021-19:45:32.026837749] msec_range[8] 10.000000 - 20.000000 : 59258 [20081021-19:45:32.028863832] msec_range[9] 5.000000 - 10.000000 : 325733 [20081021-19:45:32.030795981] msec_range[10] 2.000000 - 5.000000 : 349386 [20081021-19:45:32.032652404] msec_range[11] 1.000000 - 2.000000 : 150922 [20081021-19:45:32.034675766] msec_range[12] 0.500000 - 1.000000 : 78735 [20081021-19:45:32.036684193] msec_range[13] 0.200000 - 0.500000 : 58573 [20081021-19:45:32.038585105] msec_range[14] 0.100000 - 0.200000 : 270166 [20081021-19:45:32.040462169] msec_range[15] 0.050000 - 0.100000 : 24068 [20081021-19:45:32.042418079] msec_range[16] 0.020000 - 0.050000 : 121932 [20081021-19:45:32.044285384] msec_range[17] 0.010000 - 0.020000 : 550013 [20081021-19:45:32.046336251] msec_range[18] 0.000000 - 0.010000 : 34026657 [20081021-19:45:32.048365486] [20081021-19:45:32.050477915] [ close] 0.002000 0.007199 0.027000 1407 [20081021-19:45:32.052470012] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-19:45:32.054512606] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-19:45:32.056404401] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-19:45:32.058392260] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-19:45:32.060287193] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-19:45:32.062251613] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-19:45:32.064346061] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-19:45:32.066237034] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-19:45:32.068263842] msec_range[8] 10.000000 - 20.000000 : 0 [20081021-19:45:32.070151317] msec_range[9] 5.000000 - 10.000000 : 0 [20081021-19:45:32.072071197] msec_range[10] 2.000000 - 5.000000 : 0 [20081021-19:45:32.073984749] msec_range[11] 1.000000 - 2.000000 : 0 [20081021-19:45:32.075931071] msec_range[12] 0.500000 - 1.000000 : 0 [20081021-19:45:32.077792807] msec_range[13] 0.200000 - 0.500000 : 0 [20081021-19:45:32.079779650] msec_range[14] 0.100000 - 0.200000 : 0 [20081021-19:45:32.081700114] msec_range[15] 0.050000 - 0.100000 : 0 [20081021-19:45:32.083646662] msec_range[16] 0.020000 - 0.050000 : 2 [20081021-19:45:32.085522519] msec_range[17] 0.010000 - 0.020000 : 95 [20081021-19:45:32.087868427] msec_range[18] 0.000000 - 0.010000 : 1310 [20081021-19:45:32.089825225] [20081021-19:45:32.091771249] [20081021-19:45:32.093634716] [20081021-19:45:32.095600249] [20081021-19:45:32.097466130] 8.7% User Time [20081021-19:45:32.099404015] 118.2% System Time [20081021-19:45:32.101229827] 126.9% CPU Utilization [20081021-19:45:32.194779137] Profilers reporting [20081021-19:45:34.880059959] Profilers postprocessing [20081021-19:45:36.109837467] Stopping profiling. [20081021-19:45:36.114725458] Killing daemon. [20081021-19:45:36.616986029] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0016.08-10-21_19.40.13/analysis/oprofile.001 [20081021-19:45:36.619370735] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0016.08-10-21_19.40.13/analysis/oprofile-brief.001 [20081021-19:45:36.809561473] Processing File : mpstat.001 [20081021-19:45:36.811651319] Discovered mpstat_interval=[5] [20081021-19:45:37.389805461] Processing Directory : sar.breakout.001 [20081021-19:45:37.391992656] Discovered sar_interval=[5] [20081021-19:45:37.543691565] Processing File : iostat.001 [20081021-19:45:37.545882633] Discovered iostat_interval=[5] [20081021-19:45:42.251610115] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-10-21_1926/btrfs-nodatacow-nodatasum' [20081021-19:46:26.038729972] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081021-19:46:28.195219699] PROCESSING COMMAND : 'mount -t btrfs -o nodatacow,nodatasum /dev/ffsbdev1 /mnt/ffsb1' [20081021-19:46:28.410907444] PROCESSING COMMAND : 'run sequential_reads__threads_0128 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb num_threads=128' [20081021-19:46:28.454476429] new log requested [20081021-19:46:28.476947773] Running command ffsb [20081021-19:46:39.226420139] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb [20081021-19:46:39.234319652] Importing argument : num_threads=128 [20081021-19:46:39.251839305] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081021-19:46:39.350965942] Checking for sar... [20081021-19:46:39.353074834] found [20081021-19:46:39.408268670] Checking for sar... [20081021-19:46:39.410261712] found [20081021-19:46:39.465810191] Checking for sar... [20081021-19:46:39.467876593] found [20081021-19:46:39.550945234] Checking for gettext... [20081021-19:46:39.559927220] found [20081021-19:46:39.561936868] Checking for libiberty... [20081021-19:46:39.576363050] found [20081021-19:46:39.578051708] Checking for popt... [20081021-19:46:39.586140950] found [20081021-19:46:39.594410326] Checking for popt64... [20081021-19:46:39.596457638] found [20081021-19:46:39.598283642] Checking for oprofile... [20081021-19:46:39.600165024] found [20081021-19:46:39.650476693] opcontrol: oprofile 0.9.3 compiled on Sep 25 2008 09:52:31 [20081021-19:46:39.728559182] Daemon not running [20081021-19:46:39.749069229] Unloading oprofile module [20081021-19:46:39.940424315] Daemon not running [20081021-19:46:40.341373008] Daemon not running [20081021-19:46:40.343468138] Separate options: none [20081021-19:46:40.345415232] vmlinux file: /boot/vmlinux-2.6.27-rc7 [20081021-19:46:40.347485241] Image filter: none [20081021-19:46:40.349459896] Call-graph depth: 0 [20081021-19:46:40.464895006] FFSB version 5.2.1 started [20081021-19:46:40.467118008] [20081021-19:46:40.947525573] benchmark time = 300 [20081021-19:46:40.949682837] ThreadGroup 0 [20081021-19:46:40.951531311] ================ [20081021-19:46:40.953313247] num_threads = 128 [20081021-19:46:40.955000064] [20081021-19:46:40.956970065] read_random = off [20081021-19:46:40.958946885] read_size = 104857600 (100MB) [20081021-19:46:40.960966630] read_blocksize = 4096 (4KB) [20081021-19:46:40.963169717] read_skip = off [20081021-19:46:40.965065647] read_skipsize = 0 (0B) [20081021-19:46:40.966815318] [20081021-19:46:40.968509192] write_random = off [20081021-19:46:40.970282953] write_size = 0 (0B) [20081021-19:46:40.971988823] fsync_file = 0 [20081021-19:46:40.973706198] write_blocksize = 0 (0B) [20081021-19:46:40.975379791] wait time = 0 [20081021-19:46:40.977151329] [20081021-19:46:40.978843818] op weights [20081021-19:46:40.980673853] read = 1 (100.00%) [20081021-19:46:40.982375951] readall = 0 (0.00%) [20081021-19:46:40.984260216] write = 0 (0.00%) [20081021-19:46:40.986095207] create = 0 (0.00%) [20081021-19:46:40.987809128] append = 0 (0.00%) [20081021-19:46:40.989541271] delete = 0 (0.00%) [20081021-19:46:40.991322084] metaop = 0 (0.00%) [20081021-19:46:40.993077444] createdir = 0 (0.00%) [20081021-19:46:40.994755259] stat = 0 (0.00%) [20081021-19:46:40.996530178] writeall = 0 (0.00%) [20081021-19:46:40.998309096] writeall_fsync = 0 (0.00%) [20081021-19:46:41.000089454] open_close = 0 (0.00%) [20081021-19:46:41.001820672] [20081021-19:46:41.003624949] FileSystem /mnt/ffsb1 [20081021-19:46:41.005420297] ========== [20081021-19:46:41.007088352] num_dirs = 0 [20081021-19:46:41.008866196] starting files = 1024 [20081021-19:46:41.010589860] [20081021-19:46:41.012357003] min file size = 104857600 (100MB) [20081021-19:46:41.014051422] max file size = 104857600 (100MB) [20081021-19:46:41.015849086] directio = off [20081021-19:46:41.017659616] alignedio = on [20081021-19:46:41.019392833] bufferedio = off [20081021-19:46:41.021148190] [20081021-19:46:41.022900777] aging is off [20081021-19:46:41.024634523] current utilization = 4.47% [20081021-19:46:41.026305205] [20081021-19:46:41.028043062] checking existing fs: /mnt/ffsb1 [20081021-19:46:41.054668740] fs setup took 0 secs [20081021-19:46:41.454137471] Syncing()...0 sec [20081021-19:46:41.459135820] Starting Actual Benchmark At: Tue Oct 21 19:46:41 2008 [20081021-19:46:41.472066302] [20081021-19:51:52.942883726] Syncing()...2 sec [20081021-19:51:52.983262130] FFSB benchmark finished at: Tue Oct 21 19:51:52 2008 [20081021-19:51:52.985793852] [20081021-19:51:52.988213911] Results: [20081021-19:51:53.050634771] Benchmark took 311.38 sec [20081021-19:51:53.052463218] [20081021-19:51:53.054688634] Total Results [20081021-19:51:53.068468895] =============== [20081021-19:51:53.070557051] Throughput: 157935.08 reads/sec -> 617MB/sec [20081021-19:51:53.072755961] 157935.08 Transactions per Second [20081021-19:51:53.075038875] [20081021-19:51:53.077345673] System Call Latency statistics in millisecs [20081021-19:51:53.079464416] ===== [20081021-19:51:53.081458434] Min Avg Max Total Calls [20081021-19:51:53.083723026] ======== ======== ======== ============ [20081021-19:51:53.086050119] [ open] 0.005000 1.033084 61.139000 1921 [20081021-19:51:53.088192182] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-19:51:53.090112074] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-19:51:53.092047906] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-19:51:53.094227864] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-19:51:53.096264176] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-19:51:53.163417166] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-19:51:53.165685042] msec_range[6] 50.000000 - 100.000000 : 2 [20081021-19:51:53.167656941] msec_range[7] 20.000000 - 50.000000 : 44 [20081021-19:51:53.169775536] msec_range[8] 10.000000 - 20.000000 : 21 [20081021-19:51:53.171733020] msec_range[9] 5.000000 - 10.000000 : 8 [20081021-19:51:53.173749125] msec_range[10] 2.000000 - 5.000000 : 3 [20081021-19:51:53.175611762] msec_range[11] 1.000000 - 2.000000 : 0 [20081021-19:51:53.177670727] msec_range[12] 0.500000 - 1.000000 : 0 [20081021-19:51:53.179541670] msec_range[13] 0.200000 - 0.500000 : 1 [20081021-19:51:53.181477268] msec_range[14] 0.100000 - 0.200000 : 8 [20081021-19:51:53.183363182] msec_range[15] 0.050000 - 0.100000 : 242 [20081021-19:51:53.185319458] msec_range[16] 0.020000 - 0.050000 : 1422 [20081021-19:51:53.187140867] msec_range[17] 0.010000 - 0.020000 : 83 [20081021-19:51:53.189062356] msec_range[18] 0.000000 - 0.010000 : 87 [20081021-19:51:53.190892025] [20081021-19:51:53.192805959] [ read] 0.001000 0.795931 288.588989 49177600 [20081021-19:51:53.194681682] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-19:51:53.196583108] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-19:51:53.198412481] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-19:51:53.200324618] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-19:51:53.202199098] msec_range[4] 200.000000 - 500.000000 : 11 [20081021-19:51:53.204481859] msec_range[5] 100.000000 - 200.000000 : 10461 [20081021-19:51:53.206711474] msec_range[6] 50.000000 - 100.000000 : 200467 [20081021-19:51:53.208610822] msec_range[7] 20.000000 - 50.000000 : 550993 [20081021-19:51:53.210595184] msec_range[8] 10.000000 - 20.000000 : 328934 [20081021-19:51:53.212664691] msec_range[9] 5.000000 - 10.000000 : 162633 [20081021-19:51:53.214655941] msec_range[10] 2.000000 - 5.000000 : 87951 [20081021-19:51:53.216495284] msec_range[11] 1.000000 - 2.000000 : 31025 [20081021-19:51:53.218402741] msec_range[12] 0.500000 - 1.000000 : 18380 [20081021-19:51:53.220286832] msec_range[13] 0.200000 - 0.500000 : 85455 [20081021-19:51:53.222227711] msec_range[14] 0.100000 - 0.200000 : 419630 [20081021-19:51:53.224477566] msec_range[15] 0.050000 - 0.100000 : 41858 [20081021-19:51:53.226799532] msec_range[16] 0.020000 - 0.050000 : 288778 [20081021-19:51:53.228941416] msec_range[17] 0.010000 - 0.020000 : 1610992 [20081021-19:51:53.231107699] msec_range[18] 0.000000 - 0.010000 : 45340032 [20081021-19:51:53.233174772] [20081021-19:51:53.235387828] [ close] 0.002000 0.007866 0.640000 1921 [20081021-19:51:53.237347595] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-19:51:53.239290580] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-19:51:53.241481888] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-19:51:53.243594475] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-19:51:53.245561127] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-19:51:53.247719101] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-19:51:53.249685247] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-19:51:53.251609736] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-19:51:53.253491071] msec_range[8] 10.000000 - 20.000000 : 0 [20081021-19:51:53.255455146] msec_range[9] 5.000000 - 10.000000 : 0 [20081021-19:51:53.257351224] msec_range[10] 2.000000 - 5.000000 : 0 [20081021-19:51:53.259270732] msec_range[11] 1.000000 - 2.000000 : 0 [20081021-19:51:53.261082032] msec_range[12] 0.500000 - 1.000000 : 1 [20081021-19:51:53.263195136] msec_range[13] 0.200000 - 0.500000 : 0 [20081021-19:51:53.265424042] msec_range[14] 0.100000 - 0.200000 : 0 [20081021-19:51:53.267399131] msec_range[15] 0.050000 - 0.100000 : 0 [20081021-19:51:53.269254736] msec_range[16] 0.020000 - 0.050000 : 3 [20081021-19:51:53.271222349] msec_range[17] 0.010000 - 0.020000 : 228 [20081021-19:51:53.273149353] msec_range[18] 0.000000 - 0.010000 : 1689 [20081021-19:51:53.275082236] [20081021-19:51:53.276916214] [20081021-19:51:53.278884611] [20081021-19:51:53.280790561] [20081021-19:51:53.282682129] 12.8% User Time [20081021-19:51:53.284511315] 178.2% System Time [20081021-19:51:53.286420283] 191.1% CPU Utilization [20081021-19:51:53.288283361] Profilers reporting [20081021-19:51:56.088574631] Profilers postprocessing [20081021-19:51:56.340359244] Stopping profiling. [20081021-19:51:56.344749740] Killing daemon. [20081021-19:51:56.634423989] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0128.08-10-21_19.46.28/analysis/oprofile.001 [20081021-19:51:56.636690777] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0128.08-10-21_19.46.28/analysis/oprofile-brief.001 [20081021-19:51:56.825492597] Processing File : mpstat.001 [20081021-19:51:56.827606549] Discovered mpstat_interval=[5] [20081021-19:51:57.408333168] Processing Directory : sar.breakout.001 [20081021-19:51:57.410539291] Discovered sar_interval=[5] [20081021-19:51:57.558127543] Processing File : iostat.001 [20081021-19:51:57.560111023] Discovered iostat_interval=[5] [20081021-19:52:02.457759758] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-10-21_1926/btrfs-nodatacow-nodatasum' [20081021-19:53:04.956493292] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081021-19:53:07.198025932] PROCESSING COMMAND : 'mount -t btrfs -o nodatacow,nodatasum /dev/ffsbdev1 /mnt/ffsb1' [20081021-19:53:07.384683975] PROCESSING COMMAND : 'run random_reads__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb num_threads=1' [20081021-19:53:07.457669793] new log requested [20081021-19:53:07.486341037] Running command ffsb [20081021-19:53:18.176947698] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb [20081021-19:53:18.185265289] Importing argument : num_threads=1 [20081021-19:53:18.202797978] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081021-19:53:18.301995206] Checking for sar... [20081021-19:53:18.304283328] found [20081021-19:53:18.360279788] Checking for sar... [20081021-19:53:18.362346621] found [20081021-19:53:18.417837630] Checking for sar... [20081021-19:53:18.419911283] found [20081021-19:53:18.507525784] Checking for gettext... [20081021-19:53:18.516493496] found [20081021-19:53:18.518519377] Checking for libiberty... [20081021-19:53:18.544926989] found [20081021-19:53:18.546599992] Checking for popt... [20081021-19:53:18.554633462] found [20081021-19:53:18.563055402] Checking for popt64... [20081021-19:53:18.565095932] found [20081021-19:53:18.566814604] Checking for oprofile... [20081021-19:53:18.568910228] found [20081021-19:53:18.618102266] opcontrol: oprofile 0.9.3 compiled on Sep 25 2008 09:52:31 [20081021-19:53:18.695843119] Daemon not running [20081021-19:53:18.717669958] Unloading oprofile module [20081021-19:53:18.915155108] Daemon not running [20081021-19:53:19.323052476] Daemon not running [20081021-19:53:19.325129420] Separate options: none [20081021-19:53:19.327131844] vmlinux file: /boot/vmlinux-2.6.27-rc7 [20081021-19:53:19.329228576] Image filter: none [20081021-19:53:19.331170743] Call-graph depth: 0 [20081021-19:53:19.441979641] FFSB version 5.2.1 started [20081021-19:53:19.444043023] [20081021-19:53:19.446115799] benchmark time = 300 [20081021-19:53:19.448156635] ThreadGroup 0 [20081021-19:53:19.450055254] ================ [20081021-19:53:19.451733250] num_threads = 1 [20081021-19:53:19.453547749] [20081021-19:53:19.455324601] read_random = on [20081021-19:53:19.457003390] read_size = 5242880 (5MB) [20081021-19:53:19.458779902] read_blocksize = 4096 (4KB) [20081021-19:53:19.460880211] read_skip = off [20081021-19:53:19.463082781] read_skipsize = 0 (0B) [20081021-19:53:19.464971117] [20081021-19:53:19.466921853] write_random = off [20081021-19:53:19.468731624] write_size = 0 (0B) [20081021-19:53:19.470504506] fsync_file = 0 [20081021-19:53:19.472403860] write_blocksize = 0 (0B) [20081021-19:53:19.474241105] wait time = 0 [20081021-19:53:19.476061924] [20081021-19:53:19.477749525] op weights [20081021-19:53:19.479557102] read = 1 (100.00%) [20081021-19:53:19.481412819] readall = 0 (0.00%) [20081021-19:53:19.483144114] write = 0 (0.00%) [20081021-19:53:19.484963040] create = 0 (0.00%) [20081021-19:53:19.486732126] append = 0 (0.00%) [20081021-19:53:19.488463409] delete = 0 (0.00%) [20081021-19:53:19.490208954] metaop = 0 (0.00%) [20081021-19:53:19.492301443] createdir = 0 (0.00%) [20081021-19:53:19.494157031] stat = 0 (0.00%) [20081021-19:53:19.495903161] writeall = 0 (0.00%) [20081021-19:53:19.497604617] writeall_fsync = 0 (0.00%) [20081021-19:53:19.499390784] open_close = 0 (0.00%) [20081021-19:53:19.501223598] [20081021-19:53:19.502898241] FileSystem /mnt/ffsb1 [20081021-19:53:19.504708187] ========== [20081021-19:53:19.506506089] num_dirs = 0 [20081021-19:53:19.508300403] starting files = 1024 [20081021-19:53:19.509985687] [20081021-19:53:19.511740498] min file size = 104857600 (100MB) [20081021-19:53:19.513405145] max file size = 104857600 (100MB) [20081021-19:53:19.515175145] directio = off [20081021-19:53:19.516825028] alignedio = on [20081021-19:53:19.518567073] bufferedio = off [20081021-19:53:19.520297850] [20081021-19:53:19.522077252] aging is off [20081021-19:53:19.523716863] current utilization = 4.47% [20081021-19:53:19.525695709] [20081021-19:53:19.527483283] checking existing fs: /mnt/ffsb1 [20081021-19:53:19.542474860] fs setup took 0 secs [20081021-19:53:19.914012979] Syncing()...0 sec [20081021-19:53:19.916029377] Starting Actual Benchmark At: Tue Oct 21 19:53:19 2008 [20081021-19:53:19.928801131] [20081021-19:58:21.857213002] Syncing()...0 sec [20081021-19:58:21.859860879] FFSB benchmark finished at: Tue Oct 21 19:58:21 2008 [20081021-19:58:21.862516821] [20081021-19:58:21.864882672] Results: [20081021-19:58:21.879220460] Benchmark took 301.94 sec [20081021-19:58:21.881399591] [20081021-19:58:21.883488655] Total Results [20081021-19:58:21.898604514] =============== [20081021-19:58:21.901494123] Throughput: 568.06 reads/sec -> 2.22MB/sec [20081021-19:58:21.903843365] 568.06 Transactions per Second [20081021-19:58:21.905891181] [20081021-19:58:21.908128991] System Call Latency statistics in millisecs [20081021-19:58:21.910471382] ===== [20081021-19:58:21.912709678] Min Avg Max Total Calls [20081021-19:58:21.915243279] ======== ======== ======== ============ [20081021-19:58:21.918140021] [ open] 0.014000 0.019672 0.030000 134 [20081021-19:58:21.920868782] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-19:58:21.923475779] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-19:58:21.925945080] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-19:58:21.928347003] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-19:58:21.930802456] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-19:58:21.933012683] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-19:58:21.935172278] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-19:58:21.937177704] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-19:58:21.939285782] msec_range[8] 10.000000 - 20.000000 : 0 [20081021-19:58:21.941271010] msec_range[9] 5.000000 - 10.000000 : 0 [20081021-19:58:21.943681868] msec_range[10] 2.000000 - 5.000000 : 0 [20081021-19:58:21.946078000] msec_range[11] 1.000000 - 2.000000 : 0 [20081021-19:58:21.948684598] msec_range[12] 0.500000 - 1.000000 : 0 [20081021-19:58:21.951514560] msec_range[13] 0.200000 - 0.500000 : 0 [20081021-19:58:21.953850290] msec_range[14] 0.100000 - 0.200000 : 0 [20081021-19:58:21.956209394] msec_range[15] 0.050000 - 0.100000 : 0 [20081021-19:58:21.958381118] msec_range[16] 0.020000 - 0.050000 : 49 [20081021-19:58:21.960547460] msec_range[17] 0.010000 - 0.020000 : 85 [20081021-19:58:21.963032136] msec_range[18] 0.000000 - 0.010000 : 0 [20081021-19:58:21.965139927] [20081021-19:58:21.967181993] [ read] 0.001000 1.756064 35.834999 171520 [20081021-19:58:21.969756648] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-19:58:21.972281705] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-19:58:21.974742504] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-19:58:21.977363995] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-19:58:21.979634474] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-19:58:21.981846262] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-19:58:21.984028124] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-19:58:21.986193569] msec_range[7] 20.000000 - 50.000000 : 45 [20081021-19:58:21.988616628] msec_range[8] 10.000000 - 20.000000 : 614 [20081021-19:58:21.991482487] msec_range[9] 5.000000 - 10.000000 : 12896 [20081021-19:58:21.994745063] msec_range[10] 2.000000 - 5.000000 : 44593 [20081021-19:58:21.997215624] msec_range[11] 1.000000 - 2.000000 : 9795 [20081021-19:58:21.999573471] msec_range[12] 0.500000 - 1.000000 : 606 [20081021-19:58:22.001946712] msec_range[13] 0.200000 - 0.500000 : 96343 [20081021-19:58:22.004233267] msec_range[14] 0.100000 - 0.200000 : 166 [20081021-19:58:22.006444716] msec_range[15] 0.050000 - 0.100000 : 0 [20081021-19:58:22.008619578] msec_range[16] 0.020000 - 0.050000 : 0 [20081021-19:58:22.010950556] msec_range[17] 0.010000 - 0.020000 : 107 [20081021-19:58:22.013013644] msec_range[18] 0.000000 - 0.010000 : 6355 [20081021-19:58:22.015264632] [20081021-19:58:22.017418913] [ lseek] 0.000000 0.001157 0.013000 171520 [20081021-19:58:22.019607976] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-19:58:22.021956140] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-19:58:22.024449794] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-19:58:22.028031158] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-19:58:22.030635585] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-19:58:22.033082981] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-19:58:22.035737427] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-19:58:22.038218904] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-19:58:22.040637002] msec_range[8] 10.000000 - 20.000000 : 0 [20081021-19:58:22.042875218] msec_range[9] 5.000000 - 10.000000 : 0 [20081021-19:58:22.045023329] msec_range[10] 2.000000 - 5.000000 : 0 [20081021-19:58:22.047785006] msec_range[11] 1.000000 - 2.000000 : 0 [20081021-19:58:22.050171416] msec_range[12] 0.500000 - 1.000000 : 0 [20081021-19:58:22.053774419] msec_range[13] 0.200000 - 0.500000 : 0 [20081021-19:58:22.056210482] msec_range[14] 0.100000 - 0.200000 : 0 [20081021-19:58:22.059354849] msec_range[15] 0.050000 - 0.100000 : 0 [20081021-19:58:22.061849906] msec_range[16] 0.020000 - 0.050000 : 0 [20081021-19:58:22.064232054] msec_range[17] 0.010000 - 0.020000 : 11 [20081021-19:58:22.066484840] msec_range[18] 0.000000 - 0.010000 : 171509 [20081021-19:58:22.068789845] [20081021-19:58:22.071249785] [ close] 0.003000 0.006060 0.014000 134 [20081021-19:58:22.073435825] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-19:58:22.075592326] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-19:58:22.077759670] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-19:58:22.080083127] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-19:58:22.082497795] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-19:58:22.084781221] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-19:58:22.086928276] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-19:58:22.088892863] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-19:58:22.090910408] msec_range[8] 10.000000 - 20.000000 : 0 [20081021-19:58:22.092878214] msec_range[9] 5.000000 - 10.000000 : 0 [20081021-19:58:22.094763632] msec_range[10] 2.000000 - 5.000000 : 0 [20081021-19:58:22.096880263] msec_range[11] 1.000000 - 2.000000 : 0 [20081021-19:58:22.098882484] msec_range[12] 0.500000 - 1.000000 : 0 [20081021-19:58:22.101067831] msec_range[13] 0.200000 - 0.500000 : 0 [20081021-19:58:22.103559687] msec_range[14] 0.100000 - 0.200000 : 0 [20081021-19:58:22.105810561] msec_range[15] 0.050000 - 0.100000 : 0 [20081021-19:58:22.108026789] msec_range[16] 0.020000 - 0.050000 : 0 [20081021-19:58:22.110148944] msec_range[17] 0.010000 - 0.020000 : 1 [20081021-19:58:22.112345559] msec_range[18] 0.000000 - 0.010000 : 133 [20081021-19:58:22.114427165] [20081021-19:58:22.116751499] [20081021-19:58:22.118963733] [20081021-19:58:22.121225340] [20081021-19:58:22.123449673] 0.1% User Time [20081021-19:58:22.125572125] 2.5% System Time [20081021-19:58:22.127822561] 2.6% CPU Utilization [20081021-19:58:22.129883059] Profilers reporting [20081021-19:58:22.436116710] Profilers postprocessing [20081021-19:58:22.616888471] Stopping profiling. [20081021-19:58:22.621082925] Killing daemon. [20081021-19:58:23.815728443] Processing File : /autobench/logs/ffsb.random_reads__threads_0001.08-10-21_19.53.07/analysis/oprofile.001 [20081021-19:58:23.818012207] Processing File : /autobench/logs/ffsb.random_reads__threads_0001.08-10-21_19.53.07/analysis/oprofile-brief.001 [20081021-19:58:23.928443697] Processing File : mpstat.001 [20081021-19:58:23.930541008] Discovered mpstat_interval=[5] [20081021-19:58:24.458732320] Processing Directory : sar.breakout.001 [20081021-19:58:24.460964267] Discovered sar_interval=[5] [20081021-19:58:24.594484491] Processing File : iostat.001 [20081021-19:58:24.596762550] Discovered iostat_interval=[5] [20081021-19:58:25.257038358] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-10-21_1926/btrfs-nodatacow-nodatasum' [20081021-19:58:32.012562744] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081021-19:58:32.677852233] PROCESSING COMMAND : 'mount -t btrfs -o nodatacow,nodatasum /dev/ffsbdev1 /mnt/ffsb1' [20081021-19:58:32.808641499] PROCESSING COMMAND : 'run random_reads__threads_0016 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb num_threads=16' [20081021-19:58:32.858665113] new log requested [20081021-19:58:32.881394903] Running command ffsb [20081021-19:58:40.925431195] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb [20081021-19:58:40.931960189] Importing argument : num_threads=16 [20081021-19:58:40.949347534] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081021-19:58:41.036816706] Checking for sar... [20081021-19:58:41.039097875] found [20081021-19:58:41.095212242] Checking for sar... [20081021-19:58:41.097297524] found [20081021-19:58:41.152280981] Checking for sar... [20081021-19:58:41.154416349] found [20081021-19:58:41.227908999] Checking for gettext... [20081021-19:58:41.230048633] found [20081021-19:58:41.232106061] Checking for libiberty... [20081021-19:58:41.234175318] found [20081021-19:58:41.236156308] Checking for popt... [20081021-19:58:41.238009915] found [20081021-19:58:41.239747198] Checking for popt64... [20081021-19:58:41.241687748] found [20081021-19:58:41.243763211] Checking for oprofile... [20081021-19:58:41.245633704] found [20081021-19:58:41.291972982] opcontrol: oprofile 0.9.3 compiled on Sep 25 2008 09:52:31 [20081021-19:58:41.370678180] Daemon not running [20081021-19:58:41.380684502] Unloading oprofile module [20081021-19:58:41.479883606] Daemon not running [20081021-19:58:41.773993441] Daemon not running [20081021-19:58:41.775937309] Separate options: none [20081021-19:58:41.777918916] vmlinux file: /boot/vmlinux-2.6.27-rc7 [20081021-19:58:41.779807733] Image filter: none [20081021-19:58:41.781859672] Call-graph depth: 0 [20081021-19:58:41.880096432] FFSB version 5.2.1 started [20081021-19:58:41.882273806] [20081021-19:58:41.940724622] benchmark time = 300 [20081021-19:58:41.942753553] ThreadGroup 0 [20081021-19:58:41.944593305] ================ [20081021-19:58:41.946457995] num_threads = 16 [20081021-19:58:41.948639858] [20081021-19:58:41.950608255] read_random = on [20081021-19:58:41.952369681] read_size = 5242880 (5MB) [20081021-19:58:41.954050531] read_blocksize = 4096 (4KB) [20081021-19:58:41.955916753] read_skip = off [20081021-19:58:41.957641589] read_skipsize = 0 (0B) [20081021-19:58:41.959382755] [20081021-19:58:41.961040949] write_random = off [20081021-19:58:41.962982487] write_size = 0 (0B) [20081021-19:58:41.965067593] fsync_file = 0 [20081021-19:58:41.966954611] write_blocksize = 0 (0B) [20081021-19:58:41.968723728] wait time = 0 [20081021-19:58:41.970559053] [20081021-19:58:41.972320431] op weights [20081021-19:58:41.974033658] read = 1 (100.00%) [20081021-19:58:41.975882739] readall = 0 (0.00%) [20081021-19:58:41.977726092] write = 0 (0.00%) [20081021-19:58:41.979424874] create = 0 (0.00%) [20081021-19:58:41.981267791] append = 0 (0.00%) [20081021-19:58:41.983058453] delete = 0 (0.00%) [20081021-19:58:41.984838157] metaop = 0 (0.00%) [20081021-19:58:41.986557206] createdir = 0 (0.00%) [20081021-19:58:41.988417408] stat = 0 (0.00%) [20081021-19:58:41.990240924] writeall = 0 (0.00%) [20081021-19:58:41.991949780] writeall_fsync = 0 (0.00%) [20081021-19:58:41.993826370] open_close = 0 (0.00%) [20081021-19:58:41.995598494] [20081021-19:58:41.997371121] FileSystem /mnt/ffsb1 [20081021-19:58:41.999094415] ========== [20081021-19:58:42.000985225] num_dirs = 0 [20081021-19:58:42.002847604] starting files = 1024 [20081021-19:58:42.004561517] [20081021-19:58:42.006699046] min file size = 104857600 (100MB) [20081021-19:58:42.008734323] max file size = 104857600 (100MB) [20081021-19:58:42.010612792] directio = off [20081021-19:58:42.012316244] alignedio = on [20081021-19:58:42.014267863] bufferedio = off [20081021-19:58:42.016052257] [20081021-19:58:42.017803649] aging is off [20081021-19:58:42.019489323] current utilization = 4.47% [20081021-19:58:42.021267457] [20081021-19:58:42.022946314] checking existing fs: /mnt/ffsb1 [20081021-19:58:42.030535185] fs setup took 0 secs [20081021-19:58:42.403696862] Syncing()...0 sec [20081021-19:58:42.405634414] Starting Actual Benchmark At: Tue Oct 21 19:58:42 2008 [20081021-19:58:42.418266040] [20081021-20:03:49.088684109] Syncing()...2 sec [20081021-20:03:49.099244709] FFSB benchmark finished at: Tue Oct 21 20:03:49 2008 [20081021-20:03:49.101761427] [20081021-20:03:49.104143471] Results: [20081021-20:03:49.119823292] Benchmark took 306.67 sec [20081021-20:03:49.122142966] [20081021-20:03:49.124196866] Total Results [20081021-20:03:49.138060405] =============== [20081021-20:03:49.140183926] Throughput: 5008.59 reads/sec -> 19.6MB/sec [20081021-20:03:49.142457339] 5008.59 Transactions per Second [20081021-20:03:49.144737099] [20081021-20:03:49.146926557] System Call Latency statistics in millisecs [20081021-20:03:49.150720715] ===== [20081021-20:03:49.153024641] Min Avg Max Total Calls [20081021-20:03:49.156305848] ======== ======== ======== ============ [20081021-20:03:49.158536513] [ open] 0.006000 0.028484 4.421000 1200 [20081021-20:03:49.161055525] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-20:03:49.163486900] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-20:03:49.165726381] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-20:03:49.167895506] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-20:03:49.170093118] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-20:03:49.172152969] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-20:03:49.174541184] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-20:03:49.177687446] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-20:03:49.180179935] msec_range[8] 10.000000 - 20.000000 : 0 [20081021-20:03:49.182360513] msec_range[9] 5.000000 - 10.000000 : 0 [20081021-20:03:49.185599501] msec_range[10] 2.000000 - 5.000000 : 1 [20081021-20:03:49.187919912] msec_range[11] 1.000000 - 2.000000 : 0 [20081021-20:03:49.190276293] msec_range[12] 0.500000 - 1.000000 : 0 [20081021-20:03:49.192324999] msec_range[13] 0.200000 - 0.500000 : 0 [20081021-20:03:49.194584873] msec_range[14] 0.100000 - 0.200000 : 0 [20081021-20:03:49.197032333] msec_range[15] 0.050000 - 0.100000 : 14 [20081021-20:03:49.199386794] msec_range[16] 0.020000 - 0.050000 : 965 [20081021-20:03:49.201605784] msec_range[17] 0.010000 - 0.020000 : 206 [20081021-20:03:49.205003130] msec_range[18] 0.000000 - 0.010000 : 14 [20081021-20:03:49.207418887] [20081021-20:03:49.210557673] [ read] 0.001000 3.146569 53.995998 1536000 [20081021-20:03:49.212701438] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-20:03:49.215817352] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-20:03:49.218382164] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-20:03:49.220638828] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-20:03:49.222719664] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-20:03:49.225141722] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-20:03:49.227677212] msec_range[6] 50.000000 - 100.000000 : 1 [20081021-20:03:49.229774904] msec_range[7] 20.000000 - 50.000000 : 254 [20081021-20:03:49.232694759] msec_range[8] 10.000000 - 20.000000 : 7779 [20081021-20:03:49.235245821] msec_range[9] 5.000000 - 10.000000 : 296024 [20081021-20:03:49.237650726] msec_range[10] 2.000000 - 5.000000 : 770814 [20081021-20:03:49.239831230] msec_range[11] 1.000000 - 2.000000 : 66546 [20081021-20:03:49.241943404] msec_range[12] 0.500000 - 1.000000 : 11173 [20081021-20:03:49.244367753] msec_range[13] 0.200000 - 0.500000 : 308494 [20081021-20:03:49.246598859] msec_range[14] 0.100000 - 0.200000 : 377 [20081021-20:03:49.248720056] msec_range[15] 0.050000 - 0.100000 : 6 [20081021-20:03:49.250895079] msec_range[16] 0.020000 - 0.050000 : 396 [20081021-20:03:49.252962202] msec_range[17] 0.010000 - 0.020000 : 8002 [20081021-20:03:49.254856698] msec_range[18] 0.000000 - 0.010000 : 66134 [20081021-20:03:49.256845129] [20081021-20:03:49.259077156] [ lseek] 0.000000 0.001394 0.577000 1536000 [20081021-20:03:49.261210905] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-20:03:49.263224291] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-20:03:49.265621419] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-20:03:49.267883555] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-20:03:49.269847073] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-20:03:49.272042155] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-20:03:49.274590558] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-20:03:49.277519734] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-20:03:49.281348584] msec_range[8] 10.000000 - 20.000000 : 0 [20081021-20:03:49.284145451] msec_range[9] 5.000000 - 10.000000 : 0 [20081021-20:03:49.286738045] msec_range[10] 2.000000 - 5.000000 : 0 [20081021-20:03:49.289234310] msec_range[11] 1.000000 - 2.000000 : 0 [20081021-20:03:49.291499232] msec_range[12] 0.500000 - 1.000000 : 1 [20081021-20:03:49.293752871] msec_range[13] 0.200000 - 0.500000 : 0 [20081021-20:03:49.295840959] msec_range[14] 0.100000 - 0.200000 : 2 [20081021-20:03:49.298153597] msec_range[15] 0.050000 - 0.100000 : 13 [20081021-20:03:49.301070231] msec_range[16] 0.020000 - 0.050000 : 137 [20081021-20:03:49.303306074] msec_range[17] 0.010000 - 0.020000 : 406 [20081021-20:03:49.305450594] msec_range[18] 0.000000 - 0.010000 : 1535441 [20081021-20:03:49.307529103] [20081021-20:03:49.309788440] [ close] 0.002000 0.006646 0.033000 1200 [20081021-20:03:49.311856822] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-20:03:49.313906562] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-20:03:49.315788947] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-20:03:49.317750919] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-20:03:49.319975047] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-20:03:49.321993369] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-20:03:49.324157374] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-20:03:49.326345825] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-20:03:49.328544673] msec_range[8] 10.000000 - 20.000000 : 0 [20081021-20:03:49.331281151] msec_range[9] 5.000000 - 10.000000 : 0 [20081021-20:03:49.333685592] msec_range[10] 2.000000 - 5.000000 : 0 [20081021-20:03:49.336416869] msec_range[11] 1.000000 - 2.000000 : 0 [20081021-20:03:49.338855761] msec_range[12] 0.500000 - 1.000000 : 0 [20081021-20:03:49.341150312] msec_range[13] 0.200000 - 0.500000 : 0 [20081021-20:03:49.343261642] msec_range[14] 0.100000 - 0.200000 : 0 [20081021-20:03:49.346049897] msec_range[15] 0.050000 - 0.100000 : 0 [20081021-20:03:49.348384926] msec_range[16] 0.020000 - 0.050000 : 2 [20081021-20:03:49.351055568] msec_range[17] 0.010000 - 0.020000 : 75 [20081021-20:03:49.353123281] msec_range[18] 0.000000 - 0.010000 : 1123 [20081021-20:03:49.355366848] [20081021-20:03:49.357684639] [20081021-20:03:49.359823290] [20081021-20:03:49.361765438] [20081021-20:03:49.363772406] 1.4% User Time [20081021-20:03:49.365778112] 29.3% System Time [20081021-20:03:49.367732499] 30.7% CPU Utilization [20081021-20:03:49.369795746] Profilers reporting [20081021-20:03:50.022803420] Profilers postprocessing [20081021-20:03:51.228598459] Stopping profiling. [20081021-20:03:51.233196204] Killing daemon. [20081021-20:03:52.431069374] Processing File : /autobench/logs/ffsb.random_reads__threads_0016.08-10-21_19.58.32/analysis/oprofile.001 [20081021-20:03:52.433343229] Processing File : /autobench/logs/ffsb.random_reads__threads_0016.08-10-21_19.58.32/analysis/oprofile-brief.001 [20081021-20:03:52.551092133] Processing File : mpstat.001 [20081021-20:03:52.553366973] Discovered mpstat_interval=[5] [20081021-20:03:53.097642233] Processing Directory : sar.breakout.001 [20081021-20:03:53.099819937] Discovered sar_interval=[5] [20081021-20:03:53.241387853] Processing File : iostat.001 [20081021-20:03:53.243513462] Discovered iostat_interval=[5] [20081021-20:03:54.260084258] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-10-21_1926/btrfs-nodatacow-nodatasum' [20081021-20:04:34.669503278] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081021-20:04:37.669411092] PROCESSING COMMAND : 'mount -t btrfs -o nodatacow,nodatasum /dev/ffsbdev1 /mnt/ffsb1' [20081021-20:04:37.783061253] PROCESSING COMMAND : 'run random_reads__threads_0128 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb num_threads=128' [20081021-20:04:37.826271270] new log requested [20081021-20:04:37.855574521] Running command ffsb [20081021-20:04:45.836132488] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb [20081021-20:04:45.842355870] Importing argument : num_threads=128 [20081021-20:04:45.859605403] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081021-20:04:45.948738010] Checking for sar... [20081021-20:04:45.950893909] found [20081021-20:04:46.006482164] Checking for sar... [20081021-20:04:46.008633370] found [20081021-20:04:46.064154708] Checking for sar... [20081021-20:04:46.066202034] found [20081021-20:04:46.144330268] Checking for gettext... [20081021-20:04:46.153251407] found [20081021-20:04:46.155344793] Checking for libiberty... [20081021-20:04:46.169756734] found [20081021-20:04:46.171501387] Checking for popt... [20081021-20:04:46.179399751] found [20081021-20:04:46.187793154] Checking for popt64... [20081021-20:04:46.189913307] found [20081021-20:04:46.191684494] Checking for oprofile... [20081021-20:04:46.193531989] found [20081021-20:04:46.244249166] opcontrol: oprofile 0.9.3 compiled on Sep 25 2008 09:52:31 [20081021-20:04:46.322335285] Daemon not running [20081021-20:04:46.332403057] Unloading oprofile module [20081021-20:04:46.433294877] Daemon not running [20081021-20:04:46.727312365] Daemon not running [20081021-20:04:46.729625610] Separate options: none [20081021-20:04:46.731548949] vmlinux file: /boot/vmlinux-2.6.27-rc7 [20081021-20:04:46.733312169] Image filter: none [20081021-20:04:46.735098104] Call-graph depth: 0 [20081021-20:04:46.832956638] FFSB version 5.2.1 started [20081021-20:04:46.835147307] [20081021-20:04:47.322340014] benchmark time = 300 [20081021-20:04:47.324278660] ThreadGroup 0 [20081021-20:04:47.326075942] ================ [20081021-20:04:47.328003204] num_threads = 128 [20081021-20:04:47.330543484] [20081021-20:04:47.332522374] read_random = on [20081021-20:04:47.334315745] read_size = 5242880 (5MB) [20081021-20:04:47.336005231] read_blocksize = 4096 (4KB) [20081021-20:04:47.337831574] read_skip = off [20081021-20:04:47.339600746] read_skipsize = 0 (0B) [20081021-20:04:47.341299800] [20081021-20:04:47.343156573] write_random = off [20081021-20:04:47.345433873] write_size = 0 (0B) [20081021-20:04:47.347342610] fsync_file = 0 [20081021-20:04:47.349120347] write_blocksize = 0 (0B) [20081021-20:04:47.350967730] wait time = 0 [20081021-20:04:47.352834333] [20081021-20:04:47.354532727] op weights [20081021-20:04:47.356569607] read = 1 (100.00%) [20081021-20:04:47.358391391] readall = 0 (0.00%) [20081021-20:04:47.360160818] write = 0 (0.00%) [20081021-20:04:47.361834695] create = 0 (0.00%) [20081021-20:04:47.363634329] append = 0 (0.00%) [20081021-20:04:47.365406874] delete = 0 (0.00%) [20081021-20:04:47.367218757] metaop = 0 (0.00%) [20081021-20:04:47.368914587] createdir = 0 (0.00%) [20081021-20:04:47.370731659] stat = 0 (0.00%) [20081021-20:04:47.372554104] writeall = 0 (0.00%) [20081021-20:04:47.374290432] writeall_fsync = 0 (0.00%) [20081021-20:04:47.376093610] open_close = 0 (0.00%) [20081021-20:04:47.377972989] [20081021-20:04:47.379742626] FileSystem /mnt/ffsb1 [20081021-20:04:47.381440535] ========== [20081021-20:04:47.383264054] num_dirs = 0 [20081021-20:04:47.384979623] starting files = 1024 [20081021-20:04:47.386717855] [20081021-20:04:47.388417284] min file size = 104857600 (100MB) [20081021-20:04:47.390220911] max file size = 104857600 (100MB) [20081021-20:04:47.392054211] directio = off [20081021-20:04:47.393736502] alignedio = on [20081021-20:04:47.395794032] bufferedio = off [20081021-20:04:47.397594497] [20081021-20:04:47.399349318] aging is off [20081021-20:04:47.401041833] current utilization = 4.47% [20081021-20:04:47.402867711] [20081021-20:04:47.404598965] checking existing fs: /mnt/ffsb1 [20081021-20:04:47.406737466] fs setup took 0 secs [20081021-20:04:47.790214412] Syncing()...0 sec [20081021-20:04:47.796248331] Starting Actual Benchmark At: Tue Oct 21 20:04:47 2008 [20081021-20:04:47.809005068] [20081021-20:09:57.930365134] Syncing()...4 sec [20081021-20:09:58.038917088] FFSB benchmark finished at: Tue Oct 21 20:09:57 2008 [20081021-20:09:58.041438212] [20081021-20:09:58.043840243] Results: [20081021-20:09:58.086001181] Benchmark took 310.02 sec [20081021-20:09:58.088478829] [20081021-20:09:58.090969342] Total Results [20081021-20:09:58.104894618] =============== [20081021-20:09:58.107295072] Throughput: 22299.47 reads/sec -> 87.1MB/sec [20081021-20:09:58.109563591] 22299.47 Transactions per Second [20081021-20:09:58.111678322] [20081021-20:09:58.113619628] System Call Latency statistics in millisecs [20081021-20:09:58.115824433] ===== [20081021-20:09:58.117932947] Min Avg Max Total Calls [20081021-20:09:58.120249648] ======== ======== ======== ============ [20081021-20:09:58.122266847] [ open] 0.006000 0.035204 10.278000 5401 [20081021-20:09:58.124336282] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-20:09:58.126181374] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-20:09:58.128179398] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-20:09:58.130326077] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-20:09:58.132389504] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-20:09:58.134269060] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-20:09:58.136187351] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-20:09:58.138076352] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-20:09:58.139980068] msec_range[8] 10.000000 - 20.000000 : 1 [20081021-20:09:58.141892715] msec_range[9] 5.000000 - 10.000000 : 3 [20081021-20:09:58.143830967] msec_range[10] 2.000000 - 5.000000 : 1 [20081021-20:09:58.145660711] msec_range[11] 1.000000 - 2.000000 : 0 [20081021-20:09:58.147596733] msec_range[12] 0.500000 - 1.000000 : 0 [20081021-20:09:58.149443172] msec_range[13] 0.200000 - 0.500000 : 2 [20081021-20:09:58.151341516] msec_range[14] 0.100000 - 0.200000 : 14 [20081021-20:09:58.153176717] msec_range[15] 0.050000 - 0.100000 : 386 [20081021-20:09:58.155124771] msec_range[16] 0.020000 - 0.050000 : 4192 [20081021-20:09:58.156919315] msec_range[17] 0.010000 - 0.020000 : 675 [20081021-20:09:58.158872978] msec_range[18] 0.000000 - 0.010000 : 127 [20081021-20:09:58.160717924] [20081021-20:09:58.162650450] [ read] 0.001000 5.600784 201.520996 6913280 [20081021-20:09:58.164498945] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-20:09:58.166425506] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-20:09:58.168270236] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-20:09:58.170209552] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-20:09:58.172070970] msec_range[4] 200.000000 - 500.000000 : 1 [20081021-20:09:58.174000148] msec_range[5] 100.000000 - 200.000000 : 308 [20081021-20:09:58.175866454] msec_range[6] 50.000000 - 100.000000 : 992 [20081021-20:09:58.177840359] msec_range[7] 20.000000 - 50.000000 : 38662 [20081021-20:09:58.179899467] msec_range[8] 10.000000 - 20.000000 : 573747 [20081021-20:09:58.181969474] msec_range[9] 5.000000 - 10.000000 : 2930219 [20081021-20:09:58.184182972] msec_range[10] 2.000000 - 5.000000 : 2809796 [20081021-20:09:58.186440984] msec_range[11] 1.000000 - 2.000000 : 129096 [20081021-20:09:58.188737397] msec_range[12] 0.500000 - 1.000000 : 32323 [20081021-20:09:58.190806155] msec_range[13] 0.200000 - 0.500000 : 21600 [20081021-20:09:58.193031368] msec_range[14] 0.100000 - 0.200000 : 299 [20081021-20:09:58.195107405] msec_range[15] 0.050000 - 0.100000 : 886 [20081021-20:09:58.256475142] msec_range[16] 0.020000 - 0.050000 : 9961 [20081021-20:09:58.258831600] msec_range[17] 0.010000 - 0.020000 : 93024 [20081021-20:09:58.260823634] msec_range[18] 0.000000 - 0.010000 : 272366 [20081021-20:09:58.263682817] [20081021-20:09:58.267581949] [ lseek] 0.000000 0.001698 1.308000 6913280 [20081021-20:09:58.269708990] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-20:09:58.271865352] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-20:09:58.274108666] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-20:09:58.276322575] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-20:09:58.278381255] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-20:09:58.280256955] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-20:09:58.282230243] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-20:09:58.284122380] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-20:09:58.285970964] msec_range[8] 10.000000 - 20.000000 : 0 [20081021-20:09:58.287844891] msec_range[9] 5.000000 - 10.000000 : 0 [20081021-20:09:58.289818382] msec_range[10] 2.000000 - 5.000000 : 0 [20081021-20:09:58.291739754] msec_range[11] 1.000000 - 2.000000 : 3 [20081021-20:09:58.293796506] msec_range[12] 0.500000 - 1.000000 : 3 [20081021-20:09:58.295662741] msec_range[13] 0.200000 - 0.500000 : 93 [20081021-20:09:58.297722676] msec_range[14] 0.100000 - 0.200000 : 609 [20081021-20:09:58.299660820] msec_range[15] 0.050000 - 0.100000 : 1068 [20081021-20:09:58.301680732] msec_range[16] 0.020000 - 0.050000 : 7967 [20081021-20:09:58.303543788] msec_range[17] 0.010000 - 0.020000 : 6204 [20081021-20:09:58.305620262] msec_range[18] 0.000000 - 0.010000 : 6897333 [20081021-20:09:58.307525539] [20081021-20:09:58.309442610] [ close] 0.002000 0.007661 0.220000 5401 [20081021-20:09:58.311295000] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-20:09:58.313259791] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-20:09:58.315181592] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-20:09:58.317129020] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-20:09:58.318956226] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-20:09:58.320940925] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-20:09:58.322824114] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-20:09:58.324742926] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-20:09:58.326588378] msec_range[8] 10.000000 - 20.000000 : 0 [20081021-20:09:58.328551543] msec_range[9] 5.000000 - 10.000000 : 0 [20081021-20:09:58.330405455] msec_range[10] 2.000000 - 5.000000 : 0 [20081021-20:09:58.332339773] msec_range[11] 1.000000 - 2.000000 : 0 [20081021-20:09:58.334156291] msec_range[12] 0.500000 - 1.000000 : 0 [20081021-20:09:58.336107660] msec_range[13] 0.200000 - 0.500000 : 1 [20081021-20:09:58.337977560] msec_range[14] 0.100000 - 0.200000 : 2 [20081021-20:09:58.339913381] msec_range[15] 0.050000 - 0.100000 : 7 [20081021-20:09:58.341756561] msec_range[16] 0.020000 - 0.050000 : 39 [20081021-20:09:58.343704351] msec_range[17] 0.010000 - 0.020000 : 773 [20081021-20:09:58.345570360] msec_range[18] 0.000000 - 0.010000 : 4579 [20081021-20:09:58.347484584] [20081021-20:09:58.349331391] [20081021-20:09:58.351294900] [20081021-20:09:58.353122752] [20081021-20:09:58.354972640] 7.4% User Time [20081021-20:09:58.356839507] 172.7% System Time [20081021-20:09:58.358786368] 180.1% CPU Utilization [20081021-20:09:58.360692276] Profilers reporting [20081021-20:10:00.943835628] Profilers postprocessing [20081021-20:10:01.217248642] Stopping profiling. [20081021-20:10:01.222168054] Killing daemon. [20081021-20:10:01.909040788] Processing File : /autobench/logs/ffsb.random_reads__threads_0128.08-10-21_20.04.37/analysis/oprofile.001 [20081021-20:10:01.911458355] Processing File : /autobench/logs/ffsb.random_reads__threads_0128.08-10-21_20.04.37/analysis/oprofile-brief.001 [20081021-20:10:02.177463552] Processing File : mpstat.001 [20081021-20:10:02.179489532] Discovered mpstat_interval=[5] [20081021-20:10:02.754794363] Processing Directory : sar.breakout.001 [20081021-20:10:02.757032830] Discovered sar_interval=[5] [20081021-20:10:02.909319673] Processing File : iostat.001 [20081021-20:10:02.911358637] Discovered iostat_interval=[5] [20081021-20:10:04.481400178] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-10-21_1926/btrfs-nodatacow-nodatasum' [20081021-20:13:07.061956286] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081021-20:13:09.761675077] PROCESSING COMMAND : 'mount -t btrfs -o nodatacow,nodatasum /dev/ffsbdev1 /mnt/ffsb1' [20081021-20:13:09.891890203] PROCESSING COMMAND : 'run random_writes__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb num_threads=1' [20081021-20:13:09.937338571] new log requested [20081021-20:13:09.959423261] Running command ffsb [20081021-20:13:20.609321537] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb [20081021-20:13:20.618245248] Importing argument : num_threads=1 [20081021-20:13:20.635780354] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081021-20:13:20.730881241] Checking for sar... [20081021-20:13:20.733079901] found [20081021-20:13:20.788734924] Checking for sar... [20081021-20:13:20.790885136] found [20081021-20:13:20.846409012] Checking for sar... [20081021-20:13:20.848680887] found [20081021-20:13:20.931109668] Checking for gettext... [20081021-20:13:20.940083594] found [20081021-20:13:20.942155082] Checking for libiberty... [20081021-20:13:20.962576546] found [20081021-20:13:20.964231475] Checking for popt... [20081021-20:13:20.972293476] found [20081021-20:13:20.980736616] Checking for popt64... [20081021-20:13:20.982756753] found [20081021-20:13:20.984535904] Checking for oprofile... [20081021-20:13:20.986641349] found [20081021-20:13:21.035677787] opcontrol: oprofile 0.9.3 compiled on Sep 25 2008 09:52:31 [20081021-20:13:21.113530630] Daemon not running [20081021-20:13:21.135414028] Unloading oprofile module [20081021-20:13:21.410916124] Daemon not running [20081021-20:13:21.812193509] Daemon not running [20081021-20:13:21.814474936] Separate options: none [20081021-20:13:21.816447420] vmlinux file: /boot/vmlinux-2.6.27-rc7 [20081021-20:13:21.818528353] Image filter: none [20081021-20:13:21.820349280] Call-graph depth: 0 [20081021-20:13:21.933009838] FFSB version 5.2.1 started [20081021-20:13:21.935226031] [20081021-20:13:21.937057907] benchmark time = 300 [20081021-20:13:21.939057513] ThreadGroup 0 [20081021-20:13:21.941202439] ================ [20081021-20:13:21.943217220] num_threads = 1 [20081021-20:13:21.945318845] [20081021-20:13:21.947169709] read_random = off [20081021-20:13:21.949007802] read_size = 0 (0B) [20081021-20:13:21.950716131] read_blocksize = 0 (0B) [20081021-20:13:21.952577507] read_skip = off [20081021-20:13:21.954383131] read_skipsize = 0 (0B) [20081021-20:13:21.956182112] [20081021-20:13:21.958059959] write_random = on [20081021-20:13:21.959814753] write_size = 5242880 (5MB) [20081021-20:13:21.961602566] fsync_file = 0 [20081021-20:13:21.963332103] write_blocksize = 4096 (4KB) [20081021-20:13:21.965149238] wait time = 0 [20081021-20:13:21.966977957] [20081021-20:13:21.968682875] op weights [20081021-20:13:21.970501314] read = 0 (0.00%) [20081021-20:13:21.972183977] readall = 0 (0.00%) [20081021-20:13:21.973984646] write = 1 (100.00%) [20081021-20:13:21.975722398] create = 0 (0.00%) [20081021-20:13:21.977585807] append = 0 (0.00%) [20081021-20:13:21.979386177] delete = 0 (0.00%) [20081021-20:13:21.981172634] metaop = 0 (0.00%) [20081021-20:13:21.983038779] createdir = 0 (0.00%) [20081021-20:13:21.984826636] stat = 0 (0.00%) [20081021-20:13:21.986559440] writeall = 0 (0.00%) [20081021-20:13:21.988248863] writeall_fsync = 0 (0.00%) [20081021-20:13:21.990018804] open_close = 0 (0.00%) [20081021-20:13:21.991712022] [20081021-20:13:21.993443389] FileSystem /mnt/ffsb1 [20081021-20:13:21.995104308] ========== [20081021-20:13:21.996876701] num_dirs = 0 [20081021-20:13:21.998664913] starting files = 1024 [20081021-20:13:22.000478028] [20081021-20:13:22.002247830] min file size = 104857600 (100MB) [20081021-20:13:22.004070132] max file size = 104857600 (100MB) [20081021-20:13:22.005907957] directio = off [20081021-20:13:22.007622365] alignedio = on [20081021-20:13:22.009637105] bufferedio = off [20081021-20:13:22.011531359] [20081021-20:13:22.013290715] aging is off [20081021-20:13:22.014989334] current utilization = 4.47% [20081021-20:13:22.017046254] [20081021-20:13:22.045027997] checking existing fs: /mnt/ffsb1 [20081021-20:13:22.046850665] fs setup took 0 secs [20081021-20:13:22.443509469] Syncing()...0 sec [20081021-20:13:22.445353367] Starting Actual Benchmark At: Tue Oct 21 20:13:22 2008 [20081021-20:13:22.458064485] [20081021-20:18:32.108222969] Syncing()...8 sec [20081021-20:18:32.162072989] FFSB benchmark finished at: Tue Oct 21 20:18:31 2008 [20081021-20:18:32.164678831] [20081021-20:18:32.167061969] Results: [20081021-20:18:32.281930721] Benchmark took 309.37 sec [20081021-20:18:32.284486743] [20081021-20:18:32.286956112] Total Results [20081021-20:18:32.301423218] =============== [20081021-20:18:32.303874598] Throughput: 17265.75 writes/sec -> 67.4MB/sec [20081021-20:18:32.306156467] 17265.75 Transactions per Second [20081021-20:18:32.308316683] [20081021-20:18:32.310295263] System Call Latency statistics in millisecs [20081021-20:18:32.312615588] ===== [20081021-20:18:32.314749381] Min Avg Max Total Calls [20081021-20:18:32.316959398] ======== ======== ======== ============ [20081021-20:18:32.318774229] [ open] 0.012000 0.034428 8.920000 4173 [20081021-20:18:32.320752590] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-20:18:32.322753181] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-20:18:32.324869315] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-20:18:32.326777751] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-20:18:32.328855932] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-20:18:32.330868664] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-20:18:32.332737851] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-20:18:32.334780092] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-20:18:32.336740628] msec_range[8] 10.000000 - 20.000000 : 0 [20081021-20:18:32.338731015] msec_range[9] 5.000000 - 10.000000 : 1 [20081021-20:18:32.340595211] msec_range[10] 2.000000 - 5.000000 : 1 [20081021-20:18:32.342558005] msec_range[11] 1.000000 - 2.000000 : 1 [20081021-20:18:32.344459260] msec_range[12] 0.500000 - 1.000000 : 2 [20081021-20:18:32.346402738] msec_range[13] 0.200000 - 0.500000 : 2 [20081021-20:18:32.348389374] msec_range[14] 0.100000 - 0.200000 : 5 [20081021-20:18:32.350347488] msec_range[15] 0.050000 - 0.100000 : 378 [20081021-20:18:32.352236592] msec_range[16] 0.020000 - 0.050000 : 3244 [20081021-20:18:32.354212854] msec_range[17] 0.010000 - 0.020000 : 539 [20081021-20:18:32.356099535] msec_range[18] 0.000000 - 0.010000 : 0 [20081021-20:18:32.358033927] [20081021-20:18:32.360052297] [ write] 0.008000 0.054011 1467.751953 5341440 [20081021-20:18:32.361953960] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-20:18:32.363884434] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-20:18:32.404732143] msec_range[2] 1000.000000 - 2000.000000 : 1 [20081021-20:18:32.407226512] msec_range[3] 500.000000 - 1000.000000 : 12 [20081021-20:18:32.409369487] msec_range[4] 200.000000 - 500.000000 : 119 [20081021-20:18:32.411922922] msec_range[5] 100.000000 - 200.000000 : 1004 [20081021-20:18:32.414406925] msec_range[6] 50.000000 - 100.000000 : 10 [20081021-20:18:32.416932473] msec_range[7] 20.000000 - 50.000000 : 19 [20081021-20:18:32.419237031] msec_range[8] 10.000000 - 20.000000 : 17 [20081021-20:18:32.421423090] msec_range[9] 5.000000 - 10.000000 : 45 [20081021-20:18:32.423480287] msec_range[10] 2.000000 - 5.000000 : 198 [20081021-20:18:32.425505701] msec_range[11] 1.000000 - 2.000000 : 474 [20081021-20:18:32.427684214] msec_range[12] 0.500000 - 1.000000 : 766 [20081021-20:18:32.429852742] msec_range[13] 0.200000 - 0.500000 : 1011 [20081021-20:18:32.431945179] msec_range[14] 0.100000 - 0.200000 : 2067 [20081021-20:18:32.434001912] msec_range[15] 0.050000 - 0.100000 : 36664 [20081021-20:18:32.436076640] msec_range[16] 0.020000 - 0.050000 : 776462 [20081021-20:18:32.437973245] msec_range[17] 0.010000 - 0.020000 : 4517127 [20081021-20:18:32.440076447] msec_range[18] 0.000000 - 0.010000 : 5444 [20081021-20:18:32.442070314] [20081021-20:18:32.444042416] [ lseek] 0.000000 0.001093 0.436000 5341440 [20081021-20:18:32.445956986] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-20:18:32.447975300] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-20:18:32.450075884] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-20:18:32.451985580] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-20:18:32.453958243] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-20:18:32.456032883] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-20:18:32.458020978] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-20:18:32.460050211] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-20:18:32.461925309] msec_range[8] 10.000000 - 20.000000 : 0 [20081021-20:18:32.463952003] msec_range[9] 5.000000 - 10.000000 : 0 [20081021-20:18:32.465872560] msec_range[10] 2.000000 - 5.000000 : 0 [20081021-20:18:32.467868169] msec_range[11] 1.000000 - 2.000000 : 0 [20081021-20:18:32.470004389] msec_range[12] 0.500000 - 1.000000 : 0 [20081021-20:18:32.472208824] msec_range[13] 0.200000 - 0.500000 : 53 [20081021-20:18:32.474459069] msec_range[14] 0.100000 - 0.200000 : 5 [20081021-20:18:32.476562289] msec_range[15] 0.050000 - 0.100000 : 110 [20081021-20:18:32.478658922] msec_range[16] 0.020000 - 0.050000 : 474 [20081021-20:18:32.480542326] msec_range[17] 0.010000 - 0.020000 : 895 [20081021-20:18:32.482519798] msec_range[18] 0.000000 - 0.010000 : 5339903 [20081021-20:18:32.484415153] [20081021-20:18:32.486351008] [ close] 0.003000 0.006320 0.069000 4173 [20081021-20:18:32.488226748] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-20:18:32.490190751] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-20:18:32.492072905] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-20:18:32.493924900] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-20:18:32.495804862] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-20:18:32.498036727] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-20:18:32.500113971] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-20:18:32.502139059] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-20:18:32.504066048] msec_range[8] 10.000000 - 20.000000 : 0 [20081021-20:18:32.506156645] msec_range[9] 5.000000 - 10.000000 : 0 [20081021-20:18:32.508103207] msec_range[10] 2.000000 - 5.000000 : 0 [20081021-20:18:32.510100826] msec_range[11] 1.000000 - 2.000000 : 0 [20081021-20:18:32.512025305] msec_range[12] 0.500000 - 1.000000 : 0 [20081021-20:18:32.514101901] msec_range[13] 0.200000 - 0.500000 : 0 [20081021-20:18:32.516181139] msec_range[14] 0.100000 - 0.200000 : 0 [20081021-20:18:32.518078020] msec_range[15] 0.050000 - 0.100000 : 1 [20081021-20:18:32.520170422] msec_range[16] 0.020000 - 0.050000 : 6 [20081021-20:18:32.522259006] msec_range[17] 0.010000 - 0.020000 : 107 [20081021-20:18:32.524234955] msec_range[18] 0.000000 - 0.010000 : 4059 [20081021-20:18:32.526120085] [20081021-20:18:32.528084479] [20081021-20:18:32.529959515] [20081021-20:18:32.532029657] [20081021-20:18:32.533985210] 3.7% User Time [20081021-20:18:32.536015633] 76.2% System Time [20081021-20:18:32.537967594] 79.9% CPU Utilization [20081021-20:18:32.539930779] Profilers reporting [20081021-20:18:35.485727385] Profilers postprocessing [20081021-20:18:35.693303703] Stopping profiling. [20081021-20:18:35.697678062] Killing daemon. [20081021-20:18:35.991015652] Processing File : /autobench/logs/ffsb.random_writes__threads_0001.08-10-21_20.13.09/analysis/oprofile.001 [20081021-20:18:35.993342771] Processing File : /autobench/logs/ffsb.random_writes__threads_0001.08-10-21_20.13.09/analysis/oprofile-brief.001 [20081021-20:18:36.186200600] Processing File : mpstat.001 [20081021-20:18:36.188330021] Discovered mpstat_interval=[5] [20081021-20:18:36.983511722] Processing Directory : sar.breakout.001 [20081021-20:18:36.985698217] Discovered sar_interval=[5] [20081021-20:18:37.136232658] Processing File : iostat.001 [20081021-20:18:37.138407555] Discovered iostat_interval=[5] [20081021-20:18:41.752052302] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-10-21_1926/btrfs-nodatacow-nodatasum' [20081021-20:20:08.364971197] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081021-20:20:11.350953857] PROCESSING COMMAND : 'mount -t btrfs -o nodatacow,nodatasum /dev/ffsbdev1 /mnt/ffsb1' [20081021-20:20:11.528841878] PROCESSING COMMAND : 'run random_writes__threads_0016 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb num_threads=16' [20081021-20:20:11.572246173] new log requested [20081021-20:20:11.594635504] Running command ffsb [20081021-20:20:22.533774601] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb [20081021-20:20:22.542729510] Importing argument : num_threads=16 [20081021-20:20:22.560334110] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081021-20:20:22.655597303] Checking for sar... [20081021-20:20:22.657785262] found [20081021-20:20:22.714260956] Checking for sar... [20081021-20:20:22.716331362] found [20081021-20:20:22.771447539] Checking for sar... [20081021-20:20:22.773600253] found [20081021-20:20:22.856029880] Checking for gettext... [20081021-20:20:22.871331279] found [20081021-20:20:22.873266243] Checking for libiberty... [20081021-20:20:22.881486313] found [20081021-20:20:22.883183062] Checking for popt... [20081021-20:20:22.891198067] found [20081021-20:20:22.899675535] Checking for popt64... [20081021-20:20:22.901755329] found [20081021-20:20:22.903505820] Checking for oprofile... [20081021-20:20:22.905605294] found [20081021-20:20:22.954785441] opcontrol: oprofile 0.9.3 compiled on Sep 25 2008 09:52:31 [20081021-20:20:23.032535777] Daemon not running [20081021-20:20:23.054113025] Unloading oprofile module [20081021-20:20:23.281754484] Daemon not running [20081021-20:20:23.682784194] Daemon not running [20081021-20:20:23.684688026] Separate options: none [20081021-20:20:23.686797591] vmlinux file: /boot/vmlinux-2.6.27-rc7 [20081021-20:20:23.688798253] Image filter: none [20081021-20:20:23.690773854] Call-graph depth: 0 [20081021-20:20:23.809170486] FFSB version 5.2.1 started [20081021-20:20:23.811102892] [20081021-20:20:23.867111752] benchmark time = 300 [20081021-20:20:23.869024536] ThreadGroup 0 [20081021-20:20:23.871035670] ================ [20081021-20:20:23.872853401] num_threads = 16 [20081021-20:20:23.874974709] [20081021-20:20:23.876786300] read_random = off [20081021-20:20:23.878611375] read_size = 0 (0B) [20081021-20:20:23.880655034] read_blocksize = 0 (0B) [20081021-20:20:23.883072751] read_skip = off [20081021-20:20:23.884939558] read_skipsize = 0 (0B) [20081021-20:20:23.886813760] [20081021-20:20:23.888692810] write_random = on [20081021-20:20:23.890579316] write_size = 5242880 (5MB) [20081021-20:20:23.892388013] fsync_file = 0 [20081021-20:20:23.894147932] write_blocksize = 4096 (4KB) [20081021-20:20:23.896023110] wait time = 0 [20081021-20:20:23.898042645] [20081021-20:20:23.899984268] op weights [20081021-20:20:23.901976174] read = 0 (0.00%) [20081021-20:20:23.903733505] readall = 0 (0.00%) [20081021-20:20:23.905529105] write = 1 (100.00%) [20081021-20:20:23.907356447] create = 0 (0.00%) [20081021-20:20:23.909218850] append = 0 (0.00%) [20081021-20:20:23.910962402] delete = 0 (0.00%) [20081021-20:20:23.912742768] metaop = 0 (0.00%) [20081021-20:20:23.914672570] createdir = 0 (0.00%) [20081021-20:20:23.916450830] stat = 0 (0.00%) [20081021-20:20:23.918260016] writeall = 0 (0.00%) [20081021-20:20:23.920023157] writeall_fsync = 0 (0.00%) [20081021-20:20:23.922134500] open_close = 0 (0.00%) [20081021-20:20:23.923969195] [20081021-20:20:23.925690757] FileSystem /mnt/ffsb1 [20081021-20:20:23.927370647] ========== [20081021-20:20:23.929123381] num_dirs = 0 [20081021-20:20:23.930808120] starting files = 1024 [20081021-20:20:23.932530705] [20081021-20:20:23.934200885] min file size = 104857600 (100MB) [20081021-20:20:23.935965742] max file size = 104857600 (100MB) [20081021-20:20:23.937796281] directio = off [20081021-20:20:23.939729440] alignedio = on [20081021-20:20:23.941740325] bufferedio = off [20081021-20:20:23.943513030] [20081021-20:20:23.945319436] aging is off [20081021-20:20:23.947189755] current utilization = 4.51% [20081021-20:20:23.949107135] [20081021-20:20:23.951134917] checking existing fs: /mnt/ffsb1 [20081021-20:20:24.170660624] fs setup took 0 secs [20081021-20:20:24.550186837] Syncing()...0 sec [20081021-20:20:24.552088139] Starting Actual Benchmark At: Tue Oct 21 20:20:24 2008 [20081021-20:20:24.565394532] [20081021-20:25:39.308335298] Syncing()...9 sec [20081021-20:25:39.343561198] FFSB benchmark finished at: Tue Oct 21 20:25:39 2008 [20081021-20:25:39.346199146] [20081021-20:25:39.348701421] Results: [20081021-20:25:39.409311435] Benchmark took 314.64 sec [20081021-20:25:39.411296000] [20081021-20:25:39.413658286] Total Results [20081021-20:25:39.427450366] =============== [20081021-20:25:39.429547377] Throughput: 7648.09 writes/sec -> 29.9MB/sec [20081021-20:25:39.431784131] 7648.09 Transactions per Second [20081021-20:25:39.434161437] [20081021-20:25:39.436530548] System Call Latency statistics in millisecs [20081021-20:25:39.438883868] ===== [20081021-20:25:39.441393692] Min Avg Max Total Calls [20081021-20:25:39.443457691] ======== ======== ======== ============ [20081021-20:25:39.445548164] [ open] 0.008000 0.065014 3.248000 1880 [20081021-20:25:39.447964011] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-20:25:39.450195688] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-20:25:39.452497256] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-20:25:39.454748681] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-20:25:39.456803289] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-20:25:39.458929341] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-20:25:39.460991139] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-20:25:39.463263200] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-20:25:39.465441717] msec_range[8] 10.000000 - 20.000000 : 0 [20081021-20:25:39.520286025] msec_range[9] 5.000000 - 10.000000 : 0 [20081021-20:25:39.522661237] msec_range[10] 2.000000 - 5.000000 : 7 [20081021-20:25:39.525026034] msec_range[11] 1.000000 - 2.000000 : 16 [20081021-20:25:39.527215857] msec_range[12] 0.500000 - 1.000000 : 15 [20081021-20:25:39.529649266] msec_range[13] 0.200000 - 0.500000 : 9 [20081021-20:25:39.531892232] msec_range[14] 0.100000 - 0.200000 : 40 [20081021-20:25:39.534313283] msec_range[15] 0.050000 - 0.100000 : 401 [20081021-20:25:39.536390492] msec_range[16] 0.020000 - 0.050000 : 1314 [20081021-20:25:39.538537980] msec_range[17] 0.010000 - 0.020000 : 66 [20081021-20:25:39.540527495] msec_range[18] 0.000000 - 0.010000 : 12 [20081021-20:25:39.542601887] [20081021-20:25:39.544593125] [ write] 0.008000 2.011726 9756.667969 2406400 [20081021-20:25:39.546526898] msec_range[0] 5000.000000 - 10000.000000 : 30 [20081021-20:25:39.548397732] msec_range[1] 2000.000000 - 5000.000000 : 1210 [20081021-20:25:39.550394902] msec_range[2] 1000.000000 - 2000.000000 : 223 [20081021-20:25:39.552289386] msec_range[3] 500.000000 - 1000.000000 : 91 [20081021-20:25:39.554223196] msec_range[4] 200.000000 - 500.000000 : 195 [20081021-20:25:39.556083860] msec_range[5] 100.000000 - 200.000000 : 157 [20081021-20:25:39.558014491] msec_range[6] 50.000000 - 100.000000 : 128 [20081021-20:25:39.559976358] msec_range[7] 20.000000 - 50.000000 : 216 [20081021-20:25:39.562181703] msec_range[8] 10.000000 - 20.000000 : 689 [20081021-20:25:39.564340959] msec_range[9] 5.000000 - 10.000000 : 5443 [20081021-20:25:39.566882087] msec_range[10] 2.000000 - 5.000000 : 42746 [20081021-20:25:39.569139795] msec_range[11] 1.000000 - 2.000000 : 117770 [20081021-20:25:39.571071112] msec_range[12] 0.500000 - 1.000000 : 162307 [20081021-20:25:39.573136733] msec_range[13] 0.200000 - 0.500000 : 210851 [20081021-20:25:39.575063203] msec_range[14] 0.100000 - 0.200000 : 42424 [20081021-20:25:39.577089594] msec_range[15] 0.050000 - 0.100000 : 77705 [20081021-20:25:39.579011127] msec_range[16] 0.020000 - 0.050000 : 601548 [20081021-20:25:39.580989803] msec_range[17] 0.010000 - 0.020000 : 1141843 [20081021-20:25:39.582892313] msec_range[18] 0.000000 - 0.010000 : 824 [20081021-20:25:39.584864853] [20081021-20:25:39.586737039] [ lseek] 0.000000 0.010849 2376.436035 2406400 [20081021-20:25:39.588725379] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-20:25:39.590730116] msec_range[1] 2000.000000 - 5000.000000 : 3 [20081021-20:25:39.592709106] msec_range[2] 1000.000000 - 2000.000000 : 6 [20081021-20:25:39.594881800] msec_range[3] 500.000000 - 1000.000000 : 4 [20081021-20:25:39.597081548] msec_range[4] 200.000000 - 500.000000 : 6 [20081021-20:25:39.599431607] msec_range[5] 100.000000 - 200.000000 : 1 [20081021-20:25:39.601594448] msec_range[6] 50.000000 - 100.000000 : 1 [20081021-20:25:39.603690330] msec_range[7] 20.000000 - 50.000000 : 1 [20081021-20:25:39.605723258] msec_range[8] 10.000000 - 20.000000 : 0 [20081021-20:25:39.607813402] msec_range[9] 5.000000 - 10.000000 : 9 [20081021-20:25:39.609857998] msec_range[10] 2.000000 - 5.000000 : 129 [20081021-20:25:39.611902569] msec_range[11] 1.000000 - 2.000000 : 257 [20081021-20:25:39.613859420] msec_range[12] 0.500000 - 1.000000 : 390 [20081021-20:25:39.615912972] msec_range[13] 0.200000 - 0.500000 : 623 [20081021-20:25:39.617886884] msec_range[14] 0.100000 - 0.200000 : 336 [20081021-20:25:39.619941112] msec_range[15] 0.050000 - 0.100000 : 626 [20081021-20:25:39.621954037] msec_range[16] 0.020000 - 0.050000 : 2613 [20081021-20:25:39.623834563] msec_range[17] 0.010000 - 0.020000 : 3790 [20081021-20:25:39.625898347] msec_range[18] 0.000000 - 0.010000 : 2397605 [20081021-20:25:39.627959294] [20081021-20:25:39.629920072] [ close] 0.002000 0.008255 0.075000 1880 [20081021-20:25:39.631797408] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-20:25:39.634075923] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-20:25:39.636489327] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-20:25:39.638702060] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-20:25:39.640969127] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-20:25:39.643063594] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-20:25:39.645138959] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-20:25:39.647077755] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-20:25:39.649177470] msec_range[8] 10.000000 - 20.000000 : 0 [20081021-20:25:39.651168385] msec_range[9] 5.000000 - 10.000000 : 0 [20081021-20:25:39.653230040] msec_range[10] 2.000000 - 5.000000 : 0 [20081021-20:25:39.655206351] msec_range[11] 1.000000 - 2.000000 : 0 [20081021-20:25:39.657384144] msec_range[12] 0.500000 - 1.000000 : 0 [20081021-20:25:39.659496659] msec_range[13] 0.200000 - 0.500000 : 0 [20081021-20:25:39.661524367] msec_range[14] 0.100000 - 0.200000 : 0 [20081021-20:25:39.663681063] msec_range[15] 0.050000 - 0.100000 : 1 [20081021-20:25:39.665772477] msec_range[16] 0.020000 - 0.050000 : 15 [20081021-20:25:39.668716696] msec_range[17] 0.010000 - 0.020000 : 374 [20081021-20:25:39.670861432] msec_range[18] 0.000000 - 0.010000 : 1490 [20081021-20:25:39.673264962] [20081021-20:25:39.675733079] [20081021-20:25:39.678315044] [20081021-20:25:39.680781773] [20081021-20:25:39.684112316] 2.1% User Time [20081021-20:25:39.686478884] 140.1% System Time [20081021-20:25:39.688892792] 142.3% CPU Utilization [20081021-20:25:39.691555708] Profilers reporting [20081021-20:25:42.152428737] Profilers postprocessing [20081021-20:25:43.394854191] Stopping profiling. [20081021-20:25:43.399648855] Killing daemon. [20081021-20:25:43.644073561] Processing File : /autobench/logs/ffsb.random_writes__threads_0016.08-10-21_20.20.11/analysis/oprofile.001 [20081021-20:25:43.646286864] Processing File : /autobench/logs/ffsb.random_writes__threads_0016.08-10-21_20.20.11/analysis/oprofile-brief.001 [20081021-20:25:43.823886970] Processing File : mpstat.001 [20081021-20:25:43.826013780] Discovered mpstat_interval=[5] [20081021-20:25:44.511019946] Processing Directory : sar.breakout.001 [20081021-20:25:44.513233922] Discovered sar_interval=[5] [20081021-20:25:44.674887100] Processing File : iostat.001 [20081021-20:25:44.676970091] Discovered iostat_interval=[5] [20081021-20:25:49.381366860] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-10-21_1926/btrfs-nodatacow-nodatasum' [20081021-20:26:30.122034167] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081021-20:26:33.508628024] PROCESSING COMMAND : 'mount -t btrfs -o nodatacow,nodatasum /dev/ffsbdev1 /mnt/ffsb1' [20081021-20:26:33.710319129] PROCESSING COMMAND : 'run random_writes__threads_0128 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb num_threads=128' [20081021-20:26:33.753384082] new log requested [20081021-20:26:33.775745358] Running command ffsb [20081021-20:26:44.473121028] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb [20081021-20:26:44.480871005] Importing argument : num_threads=128 [20081021-20:26:44.498458117] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081021-20:26:44.597541537] Checking for sar... [20081021-20:26:44.599766852] found [20081021-20:26:44.655920714] Checking for sar... [20081021-20:26:44.658085108] found [20081021-20:26:44.713919190] Checking for sar... [20081021-20:26:44.716202379] found [20081021-20:26:44.803749740] Checking for gettext... [20081021-20:26:44.812706522] found [20081021-20:26:44.814759498] Checking for libiberty... [20081021-20:26:44.835105165] found [20081021-20:26:44.836848419] Checking for popt... [20081021-20:26:44.844873535] found [20081021-20:26:44.853388460] Checking for popt64... [20081021-20:26:44.855264870] found [20081021-20:26:44.857216079] Checking for oprofile... [20081021-20:26:44.859213352] found [20081021-20:26:44.908447670] opcontrol: oprofile 0.9.3 compiled on Sep 25 2008 09:52:31 [20081021-20:26:44.986720700] Daemon not running [20081021-20:26:45.007798862] Unloading oprofile module [20081021-20:26:45.242078752] Daemon not running [20081021-20:26:45.643783100] Daemon not running [20081021-20:26:45.646491862] Separate options: none [20081021-20:26:45.648687338] vmlinux file: /boot/vmlinux-2.6.27-rc7 [20081021-20:26:45.650646577] Image filter: none [20081021-20:26:45.652448588] Call-graph depth: 0 [20081021-20:26:45.770722921] FFSB version 5.2.1 started [20081021-20:26:45.772879707] [20081021-20:26:46.253926389] benchmark time = 300 [20081021-20:26:46.255944160] ThreadGroup 0 [20081021-20:26:46.257745645] ================ [20081021-20:26:46.259413270] num_threads = 128 [20081021-20:26:46.261523876] [20081021-20:26:46.263342906] read_random = off [20081021-20:26:46.265113277] read_size = 0 (0B) [20081021-20:26:46.266754263] read_blocksize = 0 (0B) [20081021-20:26:46.268681216] read_skip = off [20081021-20:26:46.270679802] read_skipsize = 0 (0B) [20081021-20:26:46.272711274] [20081021-20:26:46.274903243] write_random = on [20081021-20:26:46.276820588] write_size = 5242880 (5MB) [20081021-20:26:46.278635485] fsync_file = 0 [20081021-20:26:46.280345921] write_blocksize = 4096 (4KB) [20081021-20:26:46.282394393] wait time = 0 [20081021-20:26:46.284360860] [20081021-20:26:46.286438998] op weights [20081021-20:26:46.288129636] read = 0 (0.00%) [20081021-20:26:46.290098208] readall = 0 (0.00%) [20081021-20:26:46.292014919] write = 1 (100.00%) [20081021-20:26:46.293936122] create = 0 (0.00%) [20081021-20:26:46.295607303] append = 0 (0.00%) [20081021-20:26:46.297475530] delete = 0 (0.00%) [20081021-20:26:46.299270355] metaop = 0 (0.00%) [20081021-20:26:46.301061361] createdir = 0 (0.00%) [20081021-20:26:46.302756630] stat = 0 (0.00%) [20081021-20:26:46.304572684] writeall = 0 (0.00%) [20081021-20:26:46.306532622] writeall_fsync = 0 (0.00%) [20081021-20:26:46.308210157] open_close = 0 (0.00%) [20081021-20:26:46.310087077] [20081021-20:26:46.312036928] FileSystem /mnt/ffsb1 [20081021-20:26:46.313766487] ========== [20081021-20:26:46.315502116] num_dirs = 0 [20081021-20:26:46.317214162] starting files = 1024 [20081021-20:26:46.319186483] [20081021-20:26:46.321071047] min file size = 104857600 (100MB) [20081021-20:26:46.322752425] max file size = 104857600 (100MB) [20081021-20:26:46.324673223] directio = off [20081021-20:26:46.326754991] alignedio = on [20081021-20:26:46.328758017] bufferedio = off [20081021-20:26:46.330460300] [20081021-20:26:46.332412039] aging is off [20081021-20:26:46.334546983] current utilization = 4.59% [20081021-20:26:46.336264949] [20081021-20:26:46.337930036] checking existing fs: /mnt/ffsb1 [20081021-20:26:47.260081356] fs setup took 1 secs [20081021-20:26:47.670272325] Syncing()...0 sec [20081021-20:26:47.675389934] Starting Actual Benchmark At: Tue Oct 21 20:26:47 2008 [20081021-20:26:47.688594486] [20081021-20:33:59.571270474] Syncing()...80 sec [20081021-20:33:59.589300212] FFSB benchmark finished at: Tue Oct 21 20:33:59 2008 [20081021-20:33:59.591861425] [20081021-20:33:59.594409026] Results: [20081021-20:33:59.615459678] Benchmark took 431.90 sec [20081021-20:33:59.617993872] [20081021-20:33:59.620213064] Total Results [20081021-20:33:59.635075560] =============== [20081021-20:33:59.637322454] Throughput: 1609.26 writes/sec -> 6.29MB/sec [20081021-20:33:59.639627896] 1609.26 Transactions per Second [20081021-20:33:59.642031728] [20081021-20:33:59.644113362] System Call Latency statistics in millisecs [20081021-20:33:59.646376646] ===== [20081021-20:33:59.648456892] Min Avg Max Total Calls [20081021-20:33:59.651325905] ======== ======== ======== ============ [20081021-20:33:59.654148499] [ open] 0.006000 0.042153 4.859000 543 [20081021-20:33:59.657399353] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-20:33:59.659672835] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-20:33:59.662274544] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-20:33:59.664872346] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-20:33:59.667446658] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-20:33:59.669766962] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-20:33:59.672273023] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-20:33:59.674540886] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-20:33:59.676639086] msec_range[8] 10.000000 - 20.000000 : 0 [20081021-20:33:59.678677954] msec_range[9] 5.000000 - 10.000000 : 0 [20081021-20:33:59.680912486] msec_range[10] 2.000000 - 5.000000 : 1 [20081021-20:33:59.683070729] msec_range[11] 1.000000 - 2.000000 : 0 [20081021-20:33:59.685263030] msec_range[12] 0.500000 - 1.000000 : 5 [20081021-20:33:59.687323168] msec_range[13] 0.200000 - 0.500000 : 2 [20081021-20:33:59.689581284] msec_range[14] 0.100000 - 0.200000 : 1 [20081021-20:33:59.692190436] msec_range[15] 0.050000 - 0.100000 : 5 [20081021-20:33:59.694429683] msec_range[16] 0.020000 - 0.050000 : 380 [20081021-20:33:59.696941788] msec_range[17] 0.010000 - 0.020000 : 90 [20081021-20:33:59.699309789] msec_range[18] 0.000000 - 0.010000 : 59 [20081021-20:33:59.701493060] [20081021-20:33:59.703922314] [ write] 0.008000 61.545242 41581.183594 695040 [20081021-20:33:59.706330589] msec_range[0] 5000.000000 - 10000.000000 : 473 [20081021-20:33:59.708754955] msec_range[1] 2000.000000 - 5000.000000 : 220 [20081021-20:33:59.711301357] msec_range[2] 1000.000000 - 2000.000000 : 300 [20081021-20:33:59.713544918] msec_range[3] 500.000000 - 1000.000000 : 1474 [20081021-20:33:59.715971205] msec_range[4] 200.000000 - 500.000000 : 1876 [20081021-20:33:59.719405268] msec_range[5] 100.000000 - 200.000000 : 2900 [20081021-20:33:59.721768303] msec_range[6] 50.000000 - 100.000000 : 14596 [20081021-20:33:59.724175535] msec_range[7] 20.000000 - 50.000000 : 227732 [20081021-20:33:59.726499619] msec_range[8] 10.000000 - 20.000000 : 196492 [20081021-20:33:59.728793964] msec_range[9] 5.000000 - 10.000000 : 62116 [20081021-20:33:59.731132887] msec_range[10] 2.000000 - 5.000000 : 29499 [20081021-20:33:59.733547939] msec_range[11] 1.000000 - 2.000000 : 3964 [20081021-20:33:59.735864634] msec_range[12] 0.500000 - 1.000000 : 3639 [20081021-20:33:59.738689162] msec_range[13] 0.200000 - 0.500000 : 15968 [20081021-20:33:59.740946619] msec_range[14] 0.100000 - 0.200000 : 8360 [20081021-20:33:59.743068823] msec_range[15] 0.050000 - 0.100000 : 6783 [20081021-20:33:59.745058727] msec_range[16] 0.020000 - 0.050000 : 37689 [20081021-20:33:59.747391858] msec_range[17] 0.010000 - 0.020000 : 79498 [20081021-20:33:59.749724950] msec_range[18] 0.000000 - 0.010000 : 111 [20081021-20:33:59.751962674] [20081021-20:33:59.754776019] [ lseek] 0.000000 1.604798 40835.402344 695040 [20081021-20:33:59.756943934] msec_range[0] 5000.000000 - 10000.000000 : 13 [20081021-20:33:59.759351604] msec_range[1] 2000.000000 - 5000.000000 : 4 [20081021-20:33:59.762402436] msec_range[2] 1000.000000 - 2000.000000 : 7 [20081021-20:33:59.765090726] msec_range[3] 500.000000 - 1000.000000 : 36 [20081021-20:33:59.768628330] msec_range[4] 200.000000 - 500.000000 : 322 [20081021-20:33:59.770838343] msec_range[5] 100.000000 - 200.000000 : 540 [20081021-20:33:59.773244285] msec_range[6] 50.000000 - 100.000000 : 717 [20081021-20:33:59.775497353] msec_range[7] 20.000000 - 50.000000 : 1002 [20081021-20:33:59.777781708] msec_range[8] 10.000000 - 20.000000 : 765 [20081021-20:33:59.781093301] msec_range[9] 5.000000 - 10.000000 : 611 [20081021-20:33:59.783615248] msec_range[10] 2.000000 - 5.000000 : 742 [20081021-20:33:59.785825636] msec_range[11] 1.000000 - 2.000000 : 187 [20081021-20:33:59.788234879] msec_range[12] 0.500000 - 1.000000 : 424 [20081021-20:33:59.790374789] msec_range[13] 0.200000 - 0.500000 : 539 [20081021-20:33:59.792745125] msec_range[14] 0.100000 - 0.200000 : 474 [20081021-20:33:59.795042796] msec_range[15] 0.050000 - 0.100000 : 318 [20081021-20:33:59.797508003] msec_range[16] 0.020000 - 0.050000 : 1423 [20081021-20:33:59.800508442] msec_range[17] 0.010000 - 0.020000 : 3775 [20081021-20:33:59.803046326] msec_range[18] 0.000000 - 0.010000 : 683104 [20081021-20:33:59.805526124] [20081021-20:33:59.807865971] [ close] 0.003000 0.008924 0.107000 543 [20081021-20:33:59.810917786] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-20:33:59.813207433] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-20:33:59.815502117] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-20:33:59.818038857] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-20:33:59.820137993] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-20:33:59.822382585] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-20:33:59.824438073] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-20:33:59.826710486] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-20:33:59.829036165] msec_range[8] 10.000000 - 20.000000 : 0 [20081021-20:33:59.831067981] msec_range[9] 5.000000 - 10.000000 : 0 [20081021-20:33:59.833070755] msec_range[10] 2.000000 - 5.000000 : 0 [20081021-20:33:59.835021248] msec_range[11] 1.000000 - 2.000000 : 0 [20081021-20:33:59.836891572] msec_range[12] 0.500000 - 1.000000 : 0 [20081021-20:33:59.838920053] msec_range[13] 0.200000 - 0.500000 : 0 [20081021-20:33:59.840874829] msec_range[14] 0.100000 - 0.200000 : 1 [20081021-20:33:59.842731338] msec_range[15] 0.050000 - 0.100000 : 1 [20081021-20:33:59.845329479] msec_range[16] 0.020000 - 0.050000 : 8 [20081021-20:33:59.847711492] msec_range[17] 0.010000 - 0.020000 : 115 [20081021-20:33:59.850701562] msec_range[18] 0.000000 - 0.010000 : 418 [20081021-20:33:59.852988888] [20081021-20:33:59.855357275] [20081021-20:33:59.857489285] [20081021-20:33:59.859866962] [20081021-20:33:59.862482828] 0.3% User Time [20081021-20:33:59.865132819] 299.6% System Time [20081021-20:33:59.867721966] 300.0% CPU Utilization [20081021-20:33:59.870249744] Profilers reporting [20081021-20:34:01.080939477] Profilers postprocessing [20081021-20:34:02.275793268] Stopping profiling. [20081021-20:34:02.281275857] Killing daemon. [20081021-20:34:02.449700741] Processing File : /autobench/logs/ffsb.random_writes__threads_0128.08-10-21_20.26.33/analysis/oprofile.001 [20081021-20:34:02.451932467] Processing File : /autobench/logs/ffsb.random_writes__threads_0128.08-10-21_20.26.33/analysis/oprofile-brief.001 [20081021-20:34:02.592236714] Processing File : mpstat.001 [20081021-20:34:02.594264397] Discovered mpstat_interval=[5] [20081021-20:34:03.244870221] Processing Directory : sar.breakout.001 [20081021-20:34:03.247050955] Discovered sar_interval=[5] [20081021-20:34:03.404035134] Processing File : iostat.001 [20081021-20:34:03.406289913] Discovered iostat_interval=[5] [20081021-20:34:07.160072900] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-10-21_1926/btrfs-nodatacow-nodatasum' [20081021-20:34:25.858106500] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081021-20:34:29.045328356] PROCESSING COMMAND : 'mkfs.btrfs /dev/ffsbdev1' [20081021-20:34:29.093095541] fs created label (null) on /dev/ffsbdev1 [20081021-20:34:29.096991819] nodesize 4096 leafsize 4096 sectorsize 4096 size 2.18TB [20081021-20:34:29.098877823] Btrfs v0.16-11-gb431f25 [20081021-20:34:29.157629841] PROCESSING COMMAND : 'mount -t btrfs -o nodatacow,nodatasum /dev/ffsbdev1 /mnt/ffsb1' [20081021-20:34:29.272125487] PROCESSING COMMAND : 'run large_file_creates__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/large_file_creates.ffsb num_threads=1' [20081021-20:34:29.323159508] new log requested [20081021-20:34:29.345794382] Running command ffsb [20081021-20:34:39.057794989] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/large_file_creates.ffsb [20081021-20:34:39.066249485] Importing argument : num_threads=1 [20081021-20:34:39.083853853] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081021-20:34:39.171152128] Checking for sar... [20081021-20:34:39.173438191] found [20081021-20:34:39.229555052] Checking for sar... [20081021-20:34:39.231633830] found [20081021-20:34:39.287172211] Checking for sar... [20081021-20:34:39.289446305] found [20081021-20:34:39.411257347] Checking for gettext... [20081021-20:34:39.421924351] found [20081021-20:34:39.423954771] Checking for libiberty... [20081021-20:34:39.426044746] found [20081021-20:34:39.427888091] Checking for popt... [20081021-20:34:39.429910108] found [20081021-20:34:39.432082800] Checking for popt64... [20081021-20:34:39.434022766] found [20081021-20:34:39.435829340] Checking for oprofile... [20081021-20:34:39.437529213] found [20081021-20:34:39.475740215] opcontrol: oprofile 0.9.3 compiled on Sep 25 2008 09:52:31 [20081021-20:34:39.553574074] Daemon not running [20081021-20:34:39.576878156] Unloading oprofile module [20081021-20:34:39.764819323] Daemon not running [20081021-20:34:40.069846235] Daemon not running [20081021-20:34:40.072128051] Separate options: none [20081021-20:34:40.073979974] vmlinux file: /boot/vmlinux-2.6.27-rc7 [20081021-20:34:40.075839291] Image filter: none [20081021-20:34:40.077584632] Call-graph depth: 0 [20081021-20:34:40.175302191] FFSB version 5.2.1 started [20081021-20:34:40.177409943] [20081021-20:34:40.179358763] benchmark time = 300 [20081021-20:34:40.181264747] ThreadGroup 0 [20081021-20:34:40.183383421] ================ [20081021-20:34:40.185545514] num_threads = 1 [20081021-20:34:40.187533973] [20081021-20:34:40.189640053] read_random = off [20081021-20:34:40.191649358] read_size = 0 (0B) [20081021-20:34:40.193500582] read_blocksize = 0 (0B) [20081021-20:34:40.195378191] read_skip = off [20081021-20:34:40.197374325] read_skipsize = 0 (0B) [20081021-20:34:40.199218528] [20081021-20:34:40.201058261] write_random = off [20081021-20:34:40.202822316] write_size = 0 (0B) [20081021-20:34:40.204632145] fsync_file = 0 [20081021-20:34:40.206326428] write_blocksize = 4096 (4KB) [20081021-20:34:40.208262643] wait time = 0 [20081021-20:34:40.210038524] [20081021-20:34:40.211806211] op weights [20081021-20:34:40.213535429] read = 0 (0.00%) [20081021-20:34:40.215276462] readall = 0 (0.00%) [20081021-20:34:40.216962332] write = 0 (0.00%) [20081021-20:34:40.218741313] create = 1 (100.00%) [20081021-20:34:40.220420072] append = 0 (0.00%) [20081021-20:34:40.222145835] delete = 0 (0.00%) [20081021-20:34:40.223763583] metaop = 0 (0.00%) [20081021-20:34:40.225510411] createdir = 0 (0.00%) [20081021-20:34:40.227151981] stat = 0 (0.00%) [20081021-20:34:40.228824396] writeall = 0 (0.00%) [20081021-20:34:40.230519492] writeall_fsync = 0 (0.00%) [20081021-20:34:40.232239887] open_close = 0 (0.00%) [20081021-20:34:40.233895207] [20081021-20:34:40.235614160] FileSystem /mnt/ffsb1 [20081021-20:34:40.237303686] ========== [20081021-20:34:40.239031149] num_dirs = 0 [20081021-20:34:40.240773404] starting files = 0 [20081021-20:34:40.242506064] [20081021-20:34:40.244160886] min file size = 1073741824 (1GB) [20081021-20:34:40.245859344] max file size = 1073741824 (1GB) [20081021-20:34:40.247547707] directio = off [20081021-20:34:40.249255886] alignedio = on [20081021-20:34:40.250921480] bufferedio = off [20081021-20:34:40.252678792] [20081021-20:34:40.254346481] aging is off [20081021-20:34:40.256076555] current utilization = 0.00% [20081021-20:34:40.257759021] [20081021-20:34:40.259500905] creating new fileset /mnt/ffsb1 [20081021-20:34:40.261139155] fs setup took 0 secs [20081021-20:34:40.593385410] Syncing()...0 sec [20081021-20:34:40.595318817] Starting Actual Benchmark At: Tue Oct 21 20:34:40 2008 [20081021-20:34:40.607978076] [20081021-20:39:42.823874352] Syncing()...0 sec [20081021-20:39:42.890083489] FFSB benchmark finished at: Tue Oct 21 20:39:42 2008 [20081021-20:39:42.892707678] [20081021-20:39:42.895135456] Results: [20081021-20:39:42.922046499] Benchmark took 301.96 sec [20081021-20:39:42.923922609] [20081021-20:39:42.926183453] Total Results [20081021-20:39:42.939766801] =============== [20081021-20:39:42.942051639] Throughput: 41670.23 creates/sec -> 163MB/sec [20081021-20:39:42.944537906] 41670.23 Transactions per Second [20081021-20:39:42.946930525] [20081021-20:39:42.949090993] System Call Latency statistics in millisecs [20081021-20:39:42.951305697] ===== [20081021-20:39:42.953491324] Min Avg Max Total Calls [20081021-20:39:42.955386788] ======== ======== ======== ============ [20081021-20:39:42.957366469] [ open] 0.078000 0.156958 0.842000 48 [20081021-20:39:42.959281851] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-20:39:42.961216485] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-20:39:42.963099595] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-20:39:42.965033251] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-20:39:42.966926757] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-20:39:42.968855863] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-20:39:42.970708872] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-20:39:42.972631659] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-20:39:42.974508459] msec_range[8] 10.000000 - 20.000000 : 0 [20081021-20:39:42.976495242] msec_range[9] 5.000000 - 10.000000 : 0 [20081021-20:39:42.978343870] msec_range[10] 2.000000 - 5.000000 : 0 [20081021-20:39:42.980414441] msec_range[11] 1.000000 - 2.000000 : 0 [20081021-20:39:42.982676525] msec_range[12] 0.500000 - 1.000000 : 2 [20081021-20:39:42.984774460] msec_range[13] 0.200000 - 0.500000 : 10 [20081021-20:39:42.986958208] msec_range[14] 0.100000 - 0.200000 : 8 [20081021-20:39:42.989016658] msec_range[15] 0.050000 - 0.100000 : 28 [20081021-20:39:42.991000489] msec_range[16] 0.020000 - 0.050000 : 0 [20081021-20:39:42.992922295] msec_range[17] 0.010000 - 0.020000 : 0 [20081021-20:39:42.994954229] msec_range[18] 0.000000 - 0.010000 : 0 [20081021-20:39:42.996840629] [20081021-20:39:42.998764482] [ write] 0.012000 0.023381 13.780000 12582912 [20081021-20:39:43.000643447] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-20:39:43.002743715] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-20:39:43.004628238] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-20:39:43.006629903] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-20:39:43.008536083] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-20:39:43.010449775] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-20:39:43.012352382] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-20:39:43.014309731] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-20:39:43.016185847] msec_range[8] 10.000000 - 20.000000 : 1 [20081021-20:39:43.102190496] msec_range[9] 5.000000 - 10.000000 : 0 [20081021-20:39:43.104490048] msec_range[10] 2.000000 - 5.000000 : 2 [20081021-20:39:43.106571392] msec_range[11] 1.000000 - 2.000000 : 12 [20081021-20:39:43.109105274] msec_range[12] 0.500000 - 1.000000 : 16 [20081021-20:39:43.111125857] msec_range[13] 0.200000 - 0.500000 : 2943 [20081021-20:39:43.113082893] msec_range[14] 0.100000 - 0.200000 : 691 [20081021-20:39:43.115029176] msec_range[15] 0.050000 - 0.100000 : 84963 [20081021-20:39:43.117115739] msec_range[16] 0.020000 - 0.050000 : 6036881 [20081021-20:39:43.119100893] msec_range[17] 0.010000 - 0.020000 : 6457403 [20081021-20:39:43.121003773] msec_range[18] 0.000000 - 0.010000 : 0 [20081021-20:39:43.123152274] [20081021-20:39:43.125093858] [ close] 0.005000 0.007396 0.022000 48 [20081021-20:39:43.127041872] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-20:39:43.128898294] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-20:39:43.130855561] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-20:39:43.132720439] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-20:39:43.134690866] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-20:39:43.136562942] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-20:39:43.138454873] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-20:39:43.140347005] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-20:39:43.142279999] msec_range[8] 10.000000 - 20.000000 : 0 [20081021-20:39:43.144133263] msec_range[9] 5.000000 - 10.000000 : 0 [20081021-20:39:43.146122718] msec_range[10] 2.000000 - 5.000000 : 0 [20081021-20:39:43.148277749] msec_range[11] 1.000000 - 2.000000 : 0 [20081021-20:39:43.150153404] msec_range[12] 0.500000 - 1.000000 : 0 [20081021-20:39:43.152251124] msec_range[13] 0.200000 - 0.500000 : 0 [20081021-20:39:43.154181102] msec_range[14] 0.100000 - 0.200000 : 0 [20081021-20:39:43.156208111] msec_range[15] 0.050000 - 0.100000 : 0 [20081021-20:39:43.158428215] msec_range[16] 0.020000 - 0.050000 : 1 [20081021-20:39:43.160838834] msec_range[17] 0.010000 - 0.020000 : 4 [20081021-20:39:43.163081239] msec_range[18] 0.000000 - 0.010000 : 43 [20081021-20:39:43.165427419] [20081021-20:39:43.167521736] [20081021-20:39:43.169695517] [20081021-20:39:43.171709103] [20081021-20:39:43.173814731] 5.2% User Time [20081021-20:39:43.175834162] 94.4% System Time [20081021-20:39:43.177696134] 99.6% CPU Utilization [20081021-20:39:43.179821462] Profilers reporting [20081021-20:39:45.937948090] Profilers postprocessing [20081021-20:39:47.150707210] Stopping profiling. [20081021-20:39:47.154680013] Killing daemon. [20081021-20:39:47.424266796] Processing File : /autobench/logs/ffsb.large_file_creates__threads_0001.08-10-21_20.34.29/analysis/oprofile.001 [20081021-20:39:47.426580274] Processing File : /autobench/logs/ffsb.large_file_creates__threads_0001.08-10-21_20.34.29/analysis/oprofile-brief.001 [20081021-20:39:47.737430952] Processing File : mpstat.001 [20081021-20:39:47.739628481] Discovered mpstat_interval=[5] [20081021-20:39:48.349813075] Processing Directory : sar.breakout.001 [20081021-20:39:48.351933266] Discovered sar_interval=[5] [20081021-20:39:48.497589150] Processing File : iostat.001 [20081021-20:39:48.499736705] Discovered iostat_interval=[5] [20081021-20:39:49.889131782] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-10-21_1926/btrfs-nodatacow-nodatasum' [20081021-20:40:04.307533975] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081021-20:40:06.291016831] PROCESSING COMMAND : 'mkfs.btrfs /dev/ffsbdev1' [20081021-20:40:06.334661040] fs created label (null) on /dev/ffsbdev1 [20081021-20:40:06.339117857] nodesize 4096 leafsize 4096 sectorsize 4096 size 2.18TB [20081021-20:40:06.341105242] Btrfs v0.16-11-gb431f25 [20081021-20:40:06.398176569] PROCESSING COMMAND : 'mount -t btrfs -o nodatacow,nodatasum /dev/ffsbdev1 /mnt/ffsb1' [20081021-20:40:06.563939662] PROCESSING COMMAND : 'run large_file_creates__threads_0016 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/large_file_creates.ffsb num_threads=16' [20081021-20:40:06.619611809] new log requested [20081021-20:40:06.642012650] Running command ffsb [20081021-20:40:17.592581748] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/large_file_creates.ffsb [20081021-20:40:17.601061689] Importing argument : num_threads=16 [20081021-20:40:17.618594760] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081021-20:40:17.714898229] Checking for sar... [20081021-20:40:17.716905271] found [20081021-20:40:17.772559385] Checking for sar... [20081021-20:40:17.774523736] found [20081021-20:40:17.830394579] Checking for sar... [20081021-20:40:17.832469583] found [20081021-20:40:17.915284292] Checking for gettext... [20081021-20:40:17.930281443] found [20081021-20:40:17.932248000] Checking for libiberty... [20081021-20:40:17.940717563] found [20081021-20:40:17.942415224] Checking for popt... [20081021-20:40:17.950494706] found [20081021-20:40:17.959032737] Checking for popt64... [20081021-20:40:17.965429268] found [20081021-20:40:17.967436654] Checking for oprofile... [20081021-20:40:17.969454661] found [20081021-20:40:18.021051736] opcontrol: oprofile 0.9.3 compiled on Sep 25 2008 09:52:31 [20081021-20:40:18.099038163] Daemon not running [20081021-20:40:18.119252958] Unloading oprofile module [20081021-20:40:18.353740403] Daemon not running [20081021-20:40:18.754330333] Daemon not running [20081021-20:40:18.756231341] Separate options: none [20081021-20:40:18.758216915] vmlinux file: /boot/vmlinux-2.6.27-rc7 [20081021-20:40:18.760204689] Image filter: none [20081021-20:40:18.761988695] Call-graph depth: 0 [20081021-20:40:18.876364484] FFSB version 5.2.1 started [20081021-20:40:18.878526483] [20081021-20:40:18.932019553] benchmark time = 300 [20081021-20:40:18.934073143] ThreadGroup 0 [20081021-20:40:18.935886148] ================ [20081021-20:40:18.937908522] num_threads = 16 [20081021-20:40:18.939872165] [20081021-20:40:18.941970280] read_random = off [20081021-20:40:18.943983765] read_size = 0 (0B) [20081021-20:40:18.945940826] read_blocksize = 0 (0B) [20081021-20:40:18.947774591] read_skip = off [20081021-20:40:18.949484522] read_skipsize = 0 (0B) [20081021-20:40:18.951260201] [20081021-20:40:18.952967858] write_random = off [20081021-20:40:18.954825351] write_size = 0 (0B) [20081021-20:40:18.956662098] fsync_file = 0 [20081021-20:40:18.958405739] write_blocksize = 4096 (4KB) [20081021-20:40:18.960417720] wait time = 0 [20081021-20:40:18.962233931] [20081021-20:40:18.963967463] op weights [20081021-20:40:18.965645989] read = 0 (0.00%) [20081021-20:40:18.967409023] readall = 0 (0.00%) [20081021-20:40:18.969094497] write = 0 (0.00%) [20081021-20:40:18.970832034] create = 1 (100.00%) [20081021-20:40:18.972490970] append = 0 (0.00%) [20081021-20:40:18.974209479] delete = 0 (0.00%) [20081021-20:40:18.975898247] metaop = 0 (0.00%) [20081021-20:40:18.977622335] createdir = 0 (0.00%) [20081021-20:40:18.979268681] stat = 0 (0.00%) [20081021-20:40:18.981007425] writeall = 0 (0.00%) [20081021-20:40:18.982686196] writeall_fsync = 0 (0.00%) [20081021-20:40:18.984403151] open_close = 0 (0.00%) [20081021-20:40:18.986050321] [20081021-20:40:18.987776239] FileSystem /mnt/ffsb1 [20081021-20:40:18.989443676] ========== [20081021-20:40:18.991159959] num_dirs = 0 [20081021-20:40:18.992812888] starting files = 0 [20081021-20:40:18.994536128] [20081021-20:40:18.996211870] min file size = 1073741824 (1GB) [20081021-20:40:18.997917361] max file size = 1073741824 (1GB) [20081021-20:40:18.999615091] directio = off [20081021-20:40:19.050936936] alignedio = on [20081021-20:40:19.164924290] bufferedio = off [20081021-20:40:19.166672523] [20081021-20:40:19.168330223] aging is off [20081021-20:40:19.170274409] current utilization = 0.00% [20081021-20:40:19.172028968] [20081021-20:40:19.173751779] creating new fileset /mnt/ffsb1 [20081021-20:40:19.175404014] fs setup took 0 secs [20081021-20:40:19.377636671] Syncing()...0 sec [20081021-20:40:19.379534234] Starting Actual Benchmark At: Tue Oct 21 20:40:19 2008 [20081021-20:40:19.394535759] [20081021-20:46:12.488633144] Syncing()...0 sec [20081021-20:46:12.531194845] FFSB benchmark finished at: Tue Oct 21 20:46:12 2008 [20081021-20:46:12.533660187] [20081021-20:46:12.536088008] Results: [20081021-20:46:12.596397923] Benchmark took 352.97 sec [20081021-20:46:12.598905294] [20081021-20:46:12.601301865] Total Results [20081021-20:46:12.615140542] =============== [20081021-20:46:12.617097203] Throughput: 57186.98 creates/sec -> 223MB/sec [20081021-20:46:12.620284372] 57186.98 Transactions per Second [20081021-20:46:12.622390782] [20081021-20:46:12.624290651] System Call Latency statistics in millisecs [20081021-20:46:12.627134496] ===== [20081021-20:46:12.629643241] Min Avg Max Total Calls [20081021-20:46:12.631801168] ======== ======== ======== ============ [20081021-20:46:12.633771529] [ open] 0.095000 2.180208 62.083000 77 [20081021-20:46:12.635845046] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-20:46:12.637870101] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-20:46:12.639798541] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-20:46:12.641803889] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-20:46:12.643900035] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-20:46:12.646109974] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-20:46:12.648075024] msec_range[6] 50.000000 - 100.000000 : 1 [20081021-20:46:12.650136948] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-20:46:12.652039679] msec_range[8] 10.000000 - 20.000000 : 2 [20081021-20:46:12.654002746] msec_range[9] 5.000000 - 10.000000 : 0 [20081021-20:46:12.655893948] msec_range[10] 2.000000 - 5.000000 : 10 [20081021-20:46:12.657869328] msec_range[11] 1.000000 - 2.000000 : 17 [20081021-20:46:12.659762032] msec_range[12] 0.500000 - 1.000000 : 15 [20081021-20:46:12.661745532] msec_range[13] 0.200000 - 0.500000 : 10 [20081021-20:46:12.663639523] msec_range[14] 0.100000 - 0.200000 : 21 [20081021-20:46:12.665558725] msec_range[15] 0.050000 - 0.100000 : 1 [20081021-20:46:12.667485267] msec_range[16] 0.020000 - 0.050000 : 0 [20081021-20:46:12.669504152] msec_range[17] 0.010000 - 0.020000 : 0 [20081021-20:46:12.672781850] msec_range[18] 0.000000 - 0.010000 : 0 [20081021-20:46:12.675252599] [20081021-20:46:12.677562778] [ write] 0.013000 0.270137 63.841000 20185088 [20081021-20:46:12.680526871] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-20:46:12.682880222] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-20:46:12.685041949] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-20:46:12.687067692] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-20:46:12.689455649] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-20:46:12.691684179] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-20:46:12.693700629] msec_range[6] 50.000000 - 100.000000 : 85 [20081021-20:46:12.695542411] msec_range[7] 20.000000 - 50.000000 : 576 [20081021-20:46:12.697492490] msec_range[8] 10.000000 - 20.000000 : 10928 [20081021-20:46:12.699323864] msec_range[9] 5.000000 - 10.000000 : 165950 [20081021-20:46:12.701283151] msec_range[10] 2.000000 - 5.000000 : 703917 [20081021-20:46:12.703189165] msec_range[11] 1.000000 - 2.000000 : 328529 [20081021-20:46:12.773096375] msec_range[12] 0.500000 - 1.000000 : 602897 [20081021-20:46:12.775403540] msec_range[13] 0.200000 - 0.500000 : 1266209 [20081021-20:46:12.777627432] msec_range[14] 0.100000 - 0.200000 : 712134 [20081021-20:46:12.780556017] msec_range[15] 0.050000 - 0.100000 : 2337496 [20081021-20:46:12.782741731] msec_range[16] 0.020000 - 0.050000 : 10247017 [20081021-20:46:12.784949122] msec_range[17] 0.010000 - 0.020000 : 3809350 [20081021-20:46:12.786993905] msec_range[18] 0.000000 - 0.010000 : 0 [20081021-20:46:12.789282477] [20081021-20:46:12.791263158] [ close] 0.006000 0.009987 0.026000 77 [20081021-20:46:12.793239475] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-20:46:12.795140198] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-20:46:12.797183946] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-20:46:12.799070986] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-20:46:12.801034454] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-20:46:12.802925587] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-20:46:12.804879299] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-20:46:12.806768899] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-20:46:12.808746660] msec_range[8] 10.000000 - 20.000000 : 0 [20081021-20:46:12.810597909] msec_range[9] 5.000000 - 10.000000 : 0 [20081021-20:46:12.812539902] msec_range[10] 2.000000 - 5.000000 : 0 [20081021-20:46:12.814410749] msec_range[11] 1.000000 - 2.000000 : 0 [20081021-20:46:12.816362520] msec_range[12] 0.500000 - 1.000000 : 0 [20081021-20:46:12.818245879] msec_range[13] 0.200000 - 0.500000 : 0 [20081021-20:46:12.820178750] msec_range[14] 0.100000 - 0.200000 : 0 [20081021-20:46:12.822049184] msec_range[15] 0.050000 - 0.100000 : 0 [20081021-20:46:12.824036011] msec_range[16] 0.020000 - 0.050000 : 2 [20081021-20:46:12.825923054] msec_range[17] 0.010000 - 0.020000 : 33 [20081021-20:46:12.827854978] msec_range[18] 0.000000 - 0.010000 : 42 [20081021-20:46:12.829694549] [20081021-20:46:12.831626009] [20081021-20:46:12.833472959] [20081021-20:46:12.835380123] [20081021-20:46:12.837233986] 9.5% User Time [20081021-20:46:12.839165061] 266.3% System Time [20081021-20:46:12.841005146] 275.8% CPU Utilization [20081021-20:46:12.842945345] Profilers reporting [20081021-20:46:15.650462907] Profilers postprocessing [20081021-20:46:16.898886179] Stopping profiling. [20081021-20:46:16.903666647] Killing daemon. [20081021-20:46:17.196826268] Processing File : /autobench/logs/ffsb.large_file_creates__threads_0016.08-10-21_20.40.06/analysis/oprofile.001 [20081021-20:46:17.199130808] Processing File : /autobench/logs/ffsb.large_file_creates__threads_0016.08-10-21_20.40.06/analysis/oprofile-brief.001 [20081021-20:46:17.587523672] Processing File : mpstat.001 [20081021-20:46:17.589672579] Discovered mpstat_interval=[5] [20081021-20:46:18.236405140] Processing Directory : sar.breakout.001 [20081021-20:46:18.238627440] Discovered sar_interval=[5] [20081021-20:46:18.394949285] Processing File : iostat.001 [20081021-20:46:18.397183930] Discovered iostat_interval=[5] [20081021-20:46:23.074115875] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-10-21_1926/btrfs-nodatacow-nodatasum' [20081021-20:46:33.291523326] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081021-20:46:35.457555213] PROCESSING COMMAND : 'mkfs.btrfs /dev/ffsbdev1' [20081021-20:46:35.503244888] fs created label (null) on /dev/ffsbdev1 [20081021-20:46:35.507333569] nodesize 4096 leafsize 4096 sectorsize 4096 size 2.18TB [20081021-20:46:35.509223056] Btrfs v0.16-11-gb431f25 [20081021-20:46:35.567028157] PROCESSING COMMAND : 'mount -t btrfs -o nodatacow,nodatasum /dev/ffsbdev1 /mnt/ffsb1' [20081021-20:46:35.709165156] PROCESSING COMMAND : 'run large_file_creates__threads_0128 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/large_file_creates.ffsb num_threads=128' [20081021-20:46:35.753073310] new log requested [20081021-20:46:35.775624746] Running command ffsb [20081021-20:46:46.592588207] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/large_file_creates.ffsb [20081021-20:46:46.600760017] Importing argument : num_threads=128 [20081021-20:46:46.617936272] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081021-20:46:46.715887061] Checking for sar... [20081021-20:46:46.718056224] found [20081021-20:46:46.773449194] Checking for sar... [20081021-20:46:46.775591253] found [20081021-20:46:46.830699621] Checking for sar... [20081021-20:46:46.832785174] found [20081021-20:46:46.916021933] Checking for gettext... [20081021-20:46:46.925059090] found [20081021-20:46:46.927089595] Checking for libiberty... [20081021-20:46:46.953441831] found [20081021-20:46:46.955162890] Checking for popt... [20081021-20:46:46.963160418] found [20081021-20:46:46.971359750] Checking for popt64... [20081021-20:46:46.973505268] found [20081021-20:46:46.975336727] Checking for oprofile... [20081021-20:46:46.977193617] found [20081021-20:46:47.029692579] opcontrol: oprofile 0.9.3 compiled on Sep 25 2008 09:52:31 [20081021-20:46:47.106241259] Daemon not running [20081021-20:46:47.126306521] Unloading oprofile module [20081021-20:46:47.395951094] Daemon not running [20081021-20:46:47.796981331] Daemon not running [20081021-20:46:47.798884906] Separate options: none [20081021-20:46:47.800935892] vmlinux file: /boot/vmlinux-2.6.27-rc7 [20081021-20:46:47.802895143] Image filter: none [20081021-20:46:47.804970379] Call-graph depth: 0 [20081021-20:46:47.916255880] FFSB version 5.2.1 started [20081021-20:46:47.918492402] [20081021-20:46:48.401405585] benchmark time = 300 [20081021-20:46:48.403572162] ThreadGroup 0 [20081021-20:46:48.405532356] ================ [20081021-20:46:48.407221236] num_threads = 128 [20081021-20:46:48.409240874] [20081021-20:46:48.411079266] read_random = off [20081021-20:46:48.413103937] read_size = 0 (0B) [20081021-20:46:48.415563955] read_blocksize = 0 (0B) [20081021-20:46:48.417601013] read_skip = off [20081021-20:46:48.419538999] read_skipsize = 0 (0B) [20081021-20:46:48.421365375] [20081021-20:46:48.521424969] write_random = off [20081021-20:46:48.523258696] write_size = 0 (0B) [20081021-20:46:48.525052457] fsync_file = 0 [20081021-20:46:48.526738230] write_blocksize = 4096 (4KB) [20081021-20:46:48.528498674] wait time = 0 [20081021-20:46:48.530181327] [20081021-20:46:48.531920634] op weights [20081021-20:46:48.533594853] read = 0 (0.00%) [20081021-20:46:48.535316972] readall = 0 (0.00%) [20081021-20:46:48.536994310] write = 0 (0.00%) [20081021-20:46:48.538711972] create = 1 (100.00%) [20081021-20:46:48.540362570] append = 0 (0.00%) [20081021-20:46:48.542055721] delete = 0 (0.00%) [20081021-20:46:48.543755534] metaop = 0 (0.00%) [20081021-20:46:48.545467436] createdir = 0 (0.00%) [20081021-20:46:48.547127398] stat = 0 (0.00%) [20081021-20:46:48.548863113] writeall = 0 (0.00%) [20081021-20:46:48.550538893] writeall_fsync = 0 (0.00%) [20081021-20:46:48.552241671] open_close = 0 (0.00%) [20081021-20:46:48.553896826] [20081021-20:46:48.555650413] FileSystem /mnt/ffsb1 [20081021-20:46:48.557321127] ========== [20081021-20:46:48.559019598] num_dirs = 0 [20081021-20:46:48.560664879] starting files = 0 [20081021-20:46:48.562409844] [20081021-20:46:48.564085520] min file size = 1073741824 (1GB) [20081021-20:46:48.565807825] max file size = 1073741824 (1GB) [20081021-20:46:48.567487449] directio = off [20081021-20:46:48.569201338] alignedio = on [20081021-20:46:48.570894150] bufferedio = off [20081021-20:46:48.572604546] [20081021-20:46:48.574253102] aging is off [20081021-20:46:48.575951996] current utilization = 0.00% [20081021-20:46:48.577690314] [20081021-20:46:48.579379801] creating new fileset /mnt/ffsb1 [20081021-20:46:48.581023567] fs setup took 0 secs [20081021-20:46:48.821760212] Syncing()...0 sec [20081021-20:46:48.827185153] Starting Actual Benchmark At: Tue Oct 21 20:46:48 2008 [20081021-20:46:48.840001158] [20081021-20:57:14.020809480] Syncing()...0 sec [20081021-20:57:14.081901081] FFSB benchmark finished at: Tue Oct 21 20:57:13 2008 [20081021-20:57:14.084453943] [20081021-20:57:14.086836039] Results: [20081021-20:57:14.176366383] Benchmark took 624.93 sec [20081021-20:57:14.178194251] [20081021-20:57:14.180516901] Total Results [20081021-20:57:14.194244064] =============== [20081021-20:57:14.196402716] Throughput: 53692.82 creates/sec -> 210MB/sec [20081021-20:57:14.198698352] 53692.82 Transactions per Second [20081021-20:57:14.200835712] [20081021-20:57:14.202818341] System Call Latency statistics in millisecs [20081021-20:57:14.204758859] ===== [20081021-20:57:14.207139107] Min Avg Max Total Calls [20081021-20:57:14.209454924] ======== ======== ======== ============ [20081021-20:57:14.211608336] [ open] 3.696000 76.661742 145.511002 128 [20081021-20:57:14.213527113] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-20:57:14.215499408] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-20:57:14.217403780] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-20:57:14.219383801] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-20:57:14.221240210] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-20:57:14.223220431] msec_range[5] 100.000000 - 200.000000 : 36 [20081021-20:57:14.225104255] msec_range[6] 50.000000 - 100.000000 : 65 [20081021-20:57:14.227046454] msec_range[7] 20.000000 - 50.000000 : 11 [20081021-20:57:14.228928598] msec_range[8] 10.000000 - 20.000000 : 6 [20081021-20:57:14.230890132] msec_range[9] 5.000000 - 10.000000 : 3 [20081021-20:57:14.232757979] msec_range[10] 2.000000 - 5.000000 : 7 [20081021-20:57:14.234685170] msec_range[11] 1.000000 - 2.000000 : 0 [20081021-20:57:14.236557364] msec_range[12] 0.500000 - 1.000000 : 0 [20081021-20:57:14.238491724] msec_range[13] 0.200000 - 0.500000 : 0 [20081021-20:57:14.240323182] msec_range[14] 0.100000 - 0.200000 : 0 [20081021-20:57:14.242222009] msec_range[15] 0.050000 - 0.100000 : 0 [20081021-20:57:14.244080710] msec_range[16] 0.020000 - 0.050000 : 0 [20081021-20:57:14.246004895] msec_range[17] 0.010000 - 0.020000 : 0 [20081021-20:57:14.247844787] msec_range[18] 0.000000 - 0.010000 : 0 [20081021-20:57:14.249961116] [20081021-20:57:14.252220394] [ write] 0.013000 2.356007 484.259003 33554432 [20081021-20:57:14.254216530] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-20:57:14.256314799] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-20:57:14.258317544] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-20:57:14.260252408] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-20:57:14.262112486] msec_range[4] 200.000000 - 500.000000 : 2362 [20081021-20:57:14.264053501] msec_range[5] 100.000000 - 200.000000 : 11323 [20081021-20:57:14.265899328] msec_range[6] 50.000000 - 100.000000 : 67138 [20081021-20:57:14.267821229] msec_range[7] 20.000000 - 50.000000 : 1233453 [20081021-20:57:14.269658087] msec_range[8] 10.000000 - 20.000000 : 2044470 [20081021-20:57:14.271609381] msec_range[9] 5.000000 - 10.000000 : 747541 [20081021-20:57:14.273469900] msec_range[10] 2.000000 - 5.000000 : 226044 [20081021-20:57:14.275370930] msec_range[11] 1.000000 - 2.000000 : 53919 [20081021-20:57:14.277192930] msec_range[12] 0.500000 - 1.000000 : 41152 [20081021-20:57:14.279115768] msec_range[13] 0.200000 - 0.500000 : 165370 [20081021-20:57:14.280978270] msec_range[14] 0.100000 - 0.200000 : 839283 [20081021-20:57:14.282884358] msec_range[15] 0.050000 - 0.100000 : 3557652 [20081021-20:57:14.293006598] msec_range[16] 0.020000 - 0.050000 : 19330914 [20081021-20:57:14.294891673] msec_range[17] 0.010000 - 0.020000 : 5233811 [20081021-20:57:14.296739253] msec_range[18] 0.000000 - 0.010000 : 0 [20081021-20:57:14.298737565] [20081021-20:57:14.300597391] [ close] 0.003000 0.008836 0.022000 128 [20081021-20:57:14.302522250] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-20:57:14.304353026] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-20:57:14.306250429] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-20:57:14.308152701] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-20:57:14.310060284] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-20:57:14.311916664] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-20:57:14.313863392] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-20:57:14.315744665] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-20:57:14.317701083] msec_range[8] 10.000000 - 20.000000 : 0 [20081021-20:57:14.319545612] msec_range[9] 5.000000 - 10.000000 : 0 [20081021-20:57:14.321440231] msec_range[10] 2.000000 - 5.000000 : 0 [20081021-20:57:14.323248472] msec_range[11] 1.000000 - 2.000000 : 0 [20081021-20:57:14.325147226] msec_range[12] 0.500000 - 1.000000 : 0 [20081021-20:57:14.326962566] msec_range[13] 0.200000 - 0.500000 : 0 [20081021-20:57:14.328893141] msec_range[14] 0.100000 - 0.200000 : 0 [20081021-20:57:14.330751159] msec_range[15] 0.050000 - 0.100000 : 0 [20081021-20:57:14.332658925] msec_range[16] 0.020000 - 0.050000 : 1 [20081021-20:57:14.334473832] msec_range[17] 0.010000 - 0.020000 : 38 [20081021-20:57:14.336434311] msec_range[18] 0.000000 - 0.010000 : 89 [20081021-20:57:14.338289518] [20081021-20:57:14.340190361] [20081021-20:57:14.342013867] [20081021-20:57:14.343901849] [20081021-20:57:14.345716834] 8.9% User Time [20081021-20:57:14.347586798] 265.0% System Time [20081021-20:57:14.349414349] 273.9% CPU Utilization [20081021-20:57:14.438920422] Profilers reporting [20081021-20:57:17.268336014] Profilers postprocessing [20081021-20:57:17.495700503] Stopping profiling. [20081021-20:57:17.506346596] Killing daemon. [20081021-20:57:19.028206904] Processing File : /autobench/logs/ffsb.large_file_creates__threads_0128.08-10-21_20.46.35/analysis/oprofile.001 [20081021-20:57:19.031819370] Processing File : /autobench/logs/ffsb.large_file_creates__threads_0128.08-10-21_20.46.35/analysis/oprofile-brief.001 [20081021-20:57:19.439372156] Processing File : mpstat.001 [20081021-20:57:19.441444958] Discovered mpstat_interval=[5] [20081021-20:57:20.294686187] Processing Directory : sar.breakout.001 [20081021-20:57:20.296758138] Discovered sar_interval=[5] [20081021-20:57:20.489178347] Processing File : iostat.001 [20081021-20:57:20.491414139] Discovered iostat_interval=[5] [20081021-20:57:22.019776710] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-10-21_1926/btrfs-nodatacow-nodatasum' [20081021-20:57:37.048473620] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081021-20:57:39.363345274] PROCESSING COMMAND : 'mkfs.btrfs /dev/ffsbdev1' [20081021-20:57:39.410318075] fs created label (null) on /dev/ffsbdev1 [20081021-20:57:39.413831731] nodesize 4096 leafsize 4096 sectorsize 4096 size 2.18TB [20081021-20:57:39.415763698] Btrfs v0.16-11-gb431f25 [20081021-20:57:39.474272001] PROCESSING COMMAND : 'mount -t btrfs -o nodatacow,nodatasum /dev/ffsbdev1 /mnt/ffsb1' [20081021-20:57:39.675253778] PROCESSING COMMAND : 'run mail_server__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/mail_server.ffsb num_threads=1' [20081021-20:57:39.717550138] new log requested [20081021-20:57:39.739792103] Running command ffsb [20081021-20:57:50.359748944] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/mail_server.ffsb [20081021-20:57:50.369115696] Importing argument : num_threads=1 [20081021-20:57:50.386782638] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081021-20:57:50.485214365] Checking for sar... [20081021-20:57:50.487467165] found [20081021-20:57:50.543371353] Checking for sar... [20081021-20:57:50.545433811] found [20081021-20:57:50.600918110] Checking for sar... [20081021-20:57:50.603204372] found [20081021-20:57:50.685160057] Checking for gettext... [20081021-20:57:50.700060244] found [20081021-20:57:50.702103453] Checking for libiberty... [20081021-20:57:50.710518880] found [20081021-20:57:50.712233598] Checking for popt... [20081021-20:57:50.720278435] found [20081021-20:57:50.728318014] Checking for popt64... [20081021-20:57:50.735593872] found [20081021-20:57:50.737596455] Checking for oprofile... [20081021-20:57:50.739241335] found [20081021-20:57:50.791256917] opcontrol: oprofile 0.9.3 compiled on Sep 25 2008 09:52:31 [20081021-20:57:50.869617143] Daemon not running [20081021-20:57:50.889171890] Unloading oprofile module [20081021-20:57:51.137936589] Daemon not running [20081021-20:57:51.536232455] Daemon not running [20081021-20:57:51.538408571] Separate options: none [20081021-20:57:51.540379946] vmlinux file: /boot/vmlinux-2.6.27-rc7 [20081021-20:57:51.542460625] Image filter: none [20081021-20:57:51.544506862] Call-graph depth: 0 [20081021-20:57:51.657070032] FFSB version 5.2.1 started [20081021-20:57:51.659251634] [20081021-20:57:51.661289922] benchmark time = 300 [20081021-20:57:51.663293551] ThreadGroup 0 [20081021-20:57:51.665389878] ================ [20081021-20:57:51.667209407] num_threads = 1 [20081021-20:57:51.669263599] [20081021-20:57:51.671049912] read_random = off [20081021-20:57:51.672885320] read_size = 4096 (4KB) [20081021-20:57:51.674765688] read_blocksize = 4096 (4KB) [20081021-20:57:51.676705052] read_skip = off [20081021-20:57:51.678515859] read_skipsize = 0 (0B) [20081021-20:57:51.680257061] [20081021-20:57:51.682042079] write_random = off [20081021-20:57:51.683783641] write_size = 4096 (4KB) [20081021-20:57:51.685580913] fsync_file = 0 [20081021-20:57:51.687320131] write_blocksize = 4096 (4KB) [20081021-20:57:51.689129343] wait time = 0 [20081021-20:57:51.690943906] [20081021-20:57:51.692650603] op weights [20081021-20:57:51.694438630] read = 0 (0.00%) [20081021-20:57:51.696155252] readall = 4 (57.14%) [20081021-20:57:51.697929947] write = 0 (0.00%) [20081021-20:57:51.699661213] create = 2 (28.57%) [20081021-20:57:51.701480376] append = 0 (0.00%) [20081021-20:57:51.703282866] delete = 1 (14.29%) [20081021-20:57:51.704986240] metaop = 0 (0.00%) [20081021-20:57:51.706716894] createdir = 0 (0.00%) [20081021-20:57:51.708514397] stat = 0 (0.00%) [20081021-20:57:51.710285237] writeall = 0 (0.00%) [20081021-20:57:51.712004292] writeall_fsync = 0 (0.00%) [20081021-20:57:51.713806396] open_close = 0 (0.00%) [20081021-20:57:51.715629826] [20081021-20:57:51.717331368] FileSystem /mnt/ffsb1 [20081021-20:57:51.719136676] ========== [20081021-20:57:51.720841814] num_dirs = 1000 [20081021-20:57:51.722616054] starting files = 1000000 [20081021-20:57:51.724326539] [20081021-20:57:51.726134264] min file size = 0 (0B) [20081021-20:57:51.728262192] max file size = 0 (0B) [20081021-20:57:51.730190989] directio = off [20081021-20:57:51.731974175] alignedio = on [20081021-20:57:51.733674461] bufferedio = off [20081021-20:57:51.735508549] [20081021-20:57:51.737225876] aging is off [20081021-20:57:51.739012138] current utilization = 0.00% [20081021-20:57:51.740926882] [20081021-20:57:51.742659039] creating new fileset /mnt/ffsb1 [20081021-21:05:41.736234865] fs setup took 469 secs [20081021-21:05:42.641307835] Syncing()...1 sec [20081021-21:05:42.643584266] Starting Actual Benchmark At: Tue Oct 21 21:05:42 2008 [20081021-21:05:42.725625751] [20081021-21:10:45.994162645] Syncing()...2 sec [20081021-21:10:46.008530222] FFSB benchmark finished at: Tue Oct 21 21:10:45 2008 [20081021-21:10:46.011316700] [20081021-21:10:46.013771280] Results: [20081021-21:10:46.040453343] Benchmark took 303.34 sec [20081021-21:10:46.042328873] [20081021-21:10:46.044633214] Total Results [20081021-21:10:46.058577571] =============== [20081021-21:10:46.060730291] readall : 310442 ops (59.660343%) [20081021-21:10:46.062949030] create : 203394 ops (39.087997%) [20081021-21:10:46.064855357] delete : 6513 ops (1.251660%) [20081021-21:10:46.066910554] 1715.41 Transactions per Second [20081021-21:10:46.068961766] [20081021-21:10:46.071065892] System Call Latency statistics in millisecs [20081021-21:10:46.073319837] ===== [20081021-21:10:46.075551694] Min Avg Max Total Calls [20081021-21:10:46.077990471] ======== ======== ======== ============ [20081021-21:10:46.080142558] [ open] 0.006000 1.709054 219.130997 38626 [20081021-21:10:46.082316761] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-21:10:46.084352291] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-21:10:46.086297041] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-21:10:46.088400034] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-21:10:46.090423753] msec_range[4] 200.000000 - 500.000000 : 2 [20081021-21:10:46.092456794] msec_range[5] 100.000000 - 200.000000 : 4 [20081021-21:10:46.094435765] msec_range[6] 50.000000 - 100.000000 : 8 [20081021-21:10:46.096540145] msec_range[7] 20.000000 - 50.000000 : 99 [20081021-21:10:46.098625831] msec_range[8] 10.000000 - 20.000000 : 1862 [20081021-21:10:46.100521610] msec_range[9] 5.000000 - 10.000000 : 3119 [20081021-21:10:46.103189642] msec_range[10] 2.000000 - 5.000000 : 3029 [20081021-21:10:46.105363069] msec_range[11] 1.000000 - 2.000000 : 1115 [20081021-21:10:46.108006212] msec_range[12] 0.500000 - 1.000000 : 764 [20081021-21:10:46.110213356] msec_range[13] 0.200000 - 0.500000 : 1560 [20081021-21:10:46.112363942] msec_range[14] 0.100000 - 0.200000 : 5199 [20081021-21:10:46.114552109] msec_range[15] 0.050000 - 0.100000 : 8484 [20081021-21:10:46.117006302] msec_range[16] 0.020000 - 0.050000 : 11410 [20081021-21:10:46.119284063] msec_range[17] 0.010000 - 0.020000 : 306 [20081021-21:10:46.121738223] msec_range[18] 0.000000 - 0.010000 : 1665 [20081021-21:10:46.123948211] [20081021-21:10:46.126372001] [ read] 0.004000 0.586255 315.078003 315438 [20081021-21:10:46.128620721] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-21:10:46.130842518] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-21:10:46.132991100] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-21:10:46.135157954] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-21:10:46.137339540] msec_range[4] 200.000000 - 500.000000 : 7 [20081021-21:10:46.139612947] msec_range[5] 100.000000 - 200.000000 : 12 [20081021-21:10:46.142490462] msec_range[6] 50.000000 - 100.000000 : 36 [20081021-21:10:46.145361084] msec_range[7] 20.000000 - 50.000000 : 186 [20081021-21:10:46.147466031] msec_range[8] 10.000000 - 20.000000 : 1590 [20081021-21:10:46.149631891] msec_range[9] 5.000000 - 10.000000 : 15116 [20081021-21:10:46.151788338] msec_range[10] 2.000000 - 5.000000 : 10947 [20081021-21:10:46.153883789] msec_range[11] 1.000000 - 2.000000 : 4467 [20081021-21:10:46.156123002] msec_range[12] 0.500000 - 1.000000 : 4197 [20081021-21:10:46.158333767] msec_range[13] 0.200000 - 0.500000 : 2092 [20081021-21:10:46.160898025] msec_range[14] 0.100000 - 0.200000 : 2217 [20081021-21:10:46.163968681] msec_range[15] 0.050000 - 0.100000 : 4483 [20081021-21:10:46.166442772] msec_range[16] 0.020000 - 0.050000 : 8655 [20081021-21:10:46.168879046] msec_range[17] 0.010000 - 0.020000 : 5744 [20081021-21:10:46.171260047] msec_range[18] 0.000000 - 0.010000 : 255689 [20081021-21:10:46.173315388] [20081021-21:10:46.175646224] [ write] 0.018000 0.028566 20.988001 203394 [20081021-21:10:46.177892339] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-21:10:46.180006510] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-21:10:46.182017931] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-21:10:46.184027555] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-21:10:46.186366629] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-21:10:46.188687255] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-21:10:46.191077390] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-21:10:46.193305577] msec_range[7] 20.000000 - 50.000000 : 1 [20081021-21:10:46.195519607] msec_range[8] 10.000000 - 20.000000 : 0 [20081021-21:10:46.197711530] msec_range[9] 5.000000 - 10.000000 : 2 [20081021-21:10:46.199912175] msec_range[10] 2.000000 - 5.000000 : 6 [20081021-21:10:46.202332127] msec_range[11] 1.000000 - 2.000000 : 35 [20081021-21:10:46.204674351] msec_range[12] 0.500000 - 1.000000 : 44 [20081021-21:10:46.206948020] msec_range[13] 0.200000 - 0.500000 : 219 [20081021-21:10:46.209111346] msec_range[14] 0.100000 - 0.200000 : 3399 [20081021-21:10:46.211129115] msec_range[15] 0.050000 - 0.100000 : 10106 [20081021-21:10:46.213329083] msec_range[16] 0.020000 - 0.050000 : 182857 [20081021-21:10:46.215777538] msec_range[17] 0.010000 - 0.020000 : 6725 [20081021-21:10:46.220000268] msec_range[18] 0.000000 - 0.010000 : 0 [20081021-21:10:46.222738687] [20081021-21:10:46.225182203] [ close] 0.001000 0.002315 0.032000 38626 [20081021-21:10:46.227647161] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-21:10:46.229783148] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-21:10:46.231925538] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-21:10:46.233971004] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-21:10:46.236125334] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-21:10:46.238177728] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-21:10:46.240099226] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-21:10:46.242003802] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-21:10:46.243918550] msec_range[8] 10.000000 - 20.000000 : 0 [20081021-21:10:46.246026063] msec_range[9] 5.000000 - 10.000000 : 0 [20081021-21:10:46.248427325] msec_range[10] 2.000000 - 5.000000 : 0 [20081021-21:10:46.250828131] msec_range[11] 1.000000 - 2.000000 : 0 [20081021-21:10:46.253632959] msec_range[12] 0.500000 - 1.000000 : 0 [20081021-21:10:46.255730816] msec_range[13] 0.200000 - 0.500000 : 0 [20081021-21:10:46.258171934] msec_range[14] 0.100000 - 0.200000 : 0 [20081021-21:10:46.260541182] msec_range[15] 0.050000 - 0.100000 : 0 [20081021-21:10:46.262950813] msec_range[16] 0.020000 - 0.050000 : 3 [20081021-21:10:46.265463649] msec_range[17] 0.010000 - 0.020000 : 8 [20081021-21:10:46.267768250] msec_range[18] 0.000000 - 0.010000 : 38615 [20081021-21:10:46.269967307] [20081021-21:10:46.272661730] [20081021-21:10:46.274976594] [20081021-21:10:46.277313558] [20081021-21:10:46.279756559] 0.3% User Time [20081021-21:10:46.282146468] 23.3% System Time [20081021-21:10:46.284296628] 23.6% CPU Utilization [20081021-21:10:46.742983790] Profilers reporting [20081021-21:10:49.594683004] Profilers postprocessing [20081021-21:10:50.804290582] Stopping profiling. [20081021-21:10:50.808648692] Killing daemon. [20081021-21:10:51.217892079] Processing File : /autobench/logs/ffsb.mail_server__threads_0001.08-10-21_20.57.39/analysis/oprofile.001 [20081021-21:10:51.220138758] Processing File : /autobench/logs/ffsb.mail_server__threads_0001.08-10-21_20.57.39/analysis/oprofile-brief.001 [20081021-21:10:51.401739361] Processing File : mpstat.001 [20081021-21:10:51.403997381] Discovered mpstat_interval=[5] [20081021-21:10:51.971948408] Processing Directory : sar.breakout.001 [20081021-21:10:51.974088574] Discovered sar_interval=[5] [20081021-21:10:52.123357358] Processing File : iostat.001 [20081021-21:10:52.125344992] Discovered iostat_interval=[5] [20081021-21:10:56.901098759] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-10-21_1926/btrfs-nodatacow-nodatasum' [20081021-21:11:08.796572624] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081021-21:11:11.993194610] PROCESSING COMMAND : 'mkfs.btrfs /dev/ffsbdev1' [20081021-21:11:12.127240468] fs created label (null) on /dev/ffsbdev1 [20081021-21:11:12.131029778] nodesize 4096 leafsize 4096 sectorsize 4096 size 2.18TB [20081021-21:11:12.133023790] Btrfs v0.16-11-gb431f25 [20081021-21:11:12.192731564] PROCESSING COMMAND : 'mount -t btrfs -o nodatacow,nodatasum /dev/ffsbdev1 /mnt/ffsb1' [20081021-21:11:12.300877028] PROCESSING COMMAND : 'run mail_server__threads_0016 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/mail_server.ffsb num_threads=16' [20081021-21:11:12.346356687] new log requested [20081021-21:11:12.368597331] Running command ffsb [20081021-21:11:22.993981599] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/mail_server.ffsb [20081021-21:11:23.001658223] Importing argument : num_threads=16 [20081021-21:11:23.019321128] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081021-21:11:23.117340509] Checking for sar... [20081021-21:11:23.119507601] found [20081021-21:11:23.175150663] Checking for sar... [20081021-21:11:23.177263557] found [20081021-21:11:23.232298261] Checking for sar... [20081021-21:11:23.234330470] found [20081021-21:11:23.317386699] Checking for gettext... [20081021-21:11:23.335506163] found [20081021-21:11:23.337484882] Checking for libiberty... [20081021-21:11:23.355052069] found [20081021-21:11:23.356751887] Checking for popt... [20081021-21:11:23.364549014] found [20081021-21:11:23.372805381] Checking for popt64... [20081021-21:11:23.374897498] found [20081021-21:11:23.376667439] Checking for oprofile... [20081021-21:11:23.378609468] found [20081021-21:11:23.430325726] opcontrol: oprofile 0.9.3 compiled on Sep 25 2008 09:52:31 [20081021-21:11:23.507660599] Daemon not running [20081021-21:11:23.525565141] Unloading oprofile module [20081021-21:11:23.723884822] Daemon not running [20081021-21:11:24.110482708] Daemon not running [20081021-21:11:24.112560044] Separate options: none [20081021-21:11:24.114685205] vmlinux file: /boot/vmlinux-2.6.27-rc7 [20081021-21:11:24.116426174] Image filter: none [20081021-21:11:24.118214926] Call-graph depth: 0 [20081021-21:11:24.235031737] FFSB version 5.2.1 started [20081021-21:11:24.237161838] [20081021-21:11:24.292397794] benchmark time = 300 [20081021-21:11:24.294351918] ThreadGroup 0 [20081021-21:11:24.296392553] ================ [20081021-21:11:24.298250360] num_threads = 16 [20081021-21:11:24.300378395] [20081021-21:11:24.302451910] read_random = off [20081021-21:11:24.304498815] read_size = 4096 (4KB) [20081021-21:11:24.306257184] read_blocksize = 4096 (4KB) [20081021-21:11:24.308108995] read_skip = off [20081021-21:11:24.309913261] read_skipsize = 0 (0B) [20081021-21:11:24.311606767] [20081021-21:11:24.313576065] write_random = off [20081021-21:11:24.315429872] write_size = 4096 (4KB) [20081021-21:11:24.317229827] fsync_file = 0 [20081021-21:11:24.318952222] write_blocksize = 4096 (4KB) [20081021-21:11:24.320766161] wait time = 0 [20081021-21:11:24.322592537] [20081021-21:11:24.324302267] op weights [20081021-21:11:24.326109050] read = 0 (0.00%) [20081021-21:11:24.327822241] readall = 4 (57.14%) [20081021-21:11:24.329607828] write = 0 (0.00%) [20081021-21:11:24.331351701] create = 2 (28.57%) [20081021-21:11:24.333172462] append = 0 (0.00%) [20081021-21:11:24.334979006] delete = 1 (14.29%) [20081021-21:11:24.336708029] metaop = 0 (0.00%) [20081021-21:11:24.338531127] createdir = 0 (0.00%) [20081021-21:11:24.340244006] stat = 0 (0.00%) [20081021-21:11:24.342017261] writeall = 0 (0.00%) [20081021-21:11:24.343729217] writeall_fsync = 0 (0.00%) [20081021-21:11:24.345537286] open_close = 0 (0.00%) [20081021-21:11:24.347336648] [20081021-21:11:24.349051897] FileSystem /mnt/ffsb1 [20081021-21:11:24.350862487] ========== [20081021-21:11:24.352593946] num_dirs = 1000 [20081021-21:11:24.354392814] starting files = 1000000 [20081021-21:11:24.356088521] [20081021-21:11:24.357885620] min file size = 0 (0B) [20081021-21:11:24.359670935] max file size = 0 (0B) [20081021-21:11:24.361393145] directio = off [20081021-21:11:24.363191447] alignedio = on [20081021-21:11:24.364938815] bufferedio = off [20081021-21:11:24.366655698] [20081021-21:11:24.368417206] aging is off [20081021-21:11:24.370226922] current utilization = 0.00% [20081021-21:11:24.372041873] [20081021-21:11:24.373763528] creating new fileset /mnt/ffsb1 [20081021-21:19:13.941225898] fs setup took 469 secs [20081021-21:19:14.429749639] Syncing()...0 sec [20081021-21:19:14.432378451] Starting Actual Benchmark At: Tue Oct 21 21:19:14 2008 [20081021-21:19:14.488927030] [20081021-21:25:41.755117393] Syncing()...85 sec [20081021-21:25:41.779884518] FFSB benchmark finished at: Tue Oct 21 21:25:41 2008 [20081021-21:25:41.782630416] [20081021-21:25:41.785117969] Results: [20081021-21:25:41.843751835] Benchmark took 387.14 sec [20081021-21:25:41.846225390] [20081021-21:25:41.848333464] Total Results [20081021-21:25:41.862486920] =============== [20081021-21:25:41.864721236] readall : 948456 ops (65.110845%) [20081021-21:25:41.866970830] create : 489025 ops (33.571226%) [20081021-21:25:41.869100912] delete : 19198 ops (1.317929%) [20081021-21:25:41.871137242] 3762.69 Transactions per Second [20081021-21:25:41.873117047] [20081021-21:25:41.875245416] System Call Latency statistics in millisecs [20081021-21:25:41.877411752] ===== [20081021-21:25:41.879474536] Min Avg Max Total Calls [20081021-21:25:41.881448695] ======== ======== ======== ============ [20081021-21:25:41.883529354] [ open] 0.007000 4.537910 1082.749023 115643 [20081021-21:25:41.885543738] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-21:25:41.887558300] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-21:25:41.889541539] msec_range[2] 1000.000000 - 2000.000000 : 1 [20081021-21:25:41.891797768] msec_range[3] 500.000000 - 1000.000000 : 8 [20081021-21:25:41.893929880] msec_range[4] 200.000000 - 500.000000 : 42 [20081021-21:25:41.895815725] msec_range[5] 100.000000 - 200.000000 : 68 [20081021-21:25:41.897855089] msec_range[6] 50.000000 - 100.000000 : 399 [20081021-21:25:41.899823124] msec_range[7] 20.000000 - 50.000000 : 3895 [20081021-21:25:41.901852464] msec_range[8] 10.000000 - 20.000000 : 11419 [20081021-21:25:41.903796114] msec_range[9] 5.000000 - 10.000000 : 16839 [20081021-21:25:41.905958355] msec_range[10] 2.000000 - 5.000000 : 19166 [20081021-21:25:41.907984913] msec_range[11] 1.000000 - 2.000000 : 6826 [20081021-21:25:41.909898553] msec_range[12] 0.500000 - 1.000000 : 3872 [20081021-21:25:41.911914842] msec_range[13] 0.200000 - 0.500000 : 6497 [20081021-21:25:41.913871790] msec_range[14] 0.100000 - 0.200000 : 15989 [20081021-21:25:41.915864034] msec_range[15] 0.050000 - 0.100000 : 27553 [20081021-21:25:41.917804461] msec_range[16] 0.020000 - 0.050000 : 1483 [20081021-21:25:41.919832207] msec_range[17] 0.010000 - 0.020000 : 1538 [20081021-21:25:41.921895373] msec_range[18] 0.000000 - 0.010000 : 48 [20081021-21:25:42.050807433] [20081021-21:25:42.053210119] [ read] 0.004000 1.088636 923.556030 963498 [20081021-21:25:42.055524771] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-21:25:42.058635214] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-21:25:42.061013533] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-21:25:42.063409474] msec_range[3] 500.000000 - 1000.000000 : 23 [20081021-21:25:42.065598702] msec_range[4] 200.000000 - 500.000000 : 60 [20081021-21:25:42.067819919] msec_range[5] 100.000000 - 200.000000 : 164 [20081021-21:25:42.069848699] msec_range[6] 50.000000 - 100.000000 : 739 [20081021-21:25:42.072004940] msec_range[7] 20.000000 - 50.000000 : 6398 [20081021-21:25:42.074067977] msec_range[8] 10.000000 - 20.000000 : 23930 [20081021-21:25:42.076255210] msec_range[9] 5.000000 - 10.000000 : 43416 [20081021-21:25:42.078301594] msec_range[10] 2.000000 - 5.000000 : 28490 [20081021-21:25:42.080305257] msec_range[11] 1.000000 - 2.000000 : 7268 [20081021-21:25:42.082414433] msec_range[12] 0.500000 - 1.000000 : 14025 [20081021-21:25:42.084444937] msec_range[13] 0.200000 - 0.500000 : 4287 [20081021-21:25:42.086452530] msec_range[14] 0.100000 - 0.200000 : 12159 [20081021-21:25:42.088817687] msec_range[15] 0.050000 - 0.100000 : 24067 [20081021-21:25:42.090837519] msec_range[16] 0.020000 - 0.050000 : 32386 [20081021-21:25:42.092850517] msec_range[17] 0.010000 - 0.020000 : 27431 [20081021-21:25:42.096131391] msec_range[18] 0.000000 - 0.010000 : 738655 [20081021-21:25:42.098177694] [20081021-21:25:42.100401146] [ write] 0.018000 4.592465 779.090027 489025 [20081021-21:25:42.102631787] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-21:25:42.105010557] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-21:25:42.106972209] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-21:25:42.109034367] msec_range[3] 500.000000 - 1000.000000 : 38 [20081021-21:25:42.111105148] msec_range[4] 200.000000 - 500.000000 : 172 [20081021-21:25:42.113038171] msec_range[5] 100.000000 - 200.000000 : 146 [20081021-21:25:42.115135716] msec_range[6] 50.000000 - 100.000000 : 876 [20081021-21:25:42.117218079] msec_range[7] 20.000000 - 50.000000 : 11578 [20081021-21:25:42.119276174] msec_range[8] 10.000000 - 20.000000 : 45464 [20081021-21:25:42.121176093] msec_range[9] 5.000000 - 10.000000 : 77697 [20081021-21:25:42.123243958] msec_range[10] 2.000000 - 5.000000 : 142394 [20081021-21:25:42.125296093] msec_range[11] 1.000000 - 2.000000 : 78145 [20081021-21:25:42.127205026] msec_range[12] 0.500000 - 1.000000 : 51592 [20081021-21:25:42.129235121] msec_range[13] 0.200000 - 0.500000 : 24738 [20081021-21:25:42.131226562] msec_range[14] 0.100000 - 0.200000 : 20627 [20081021-21:25:42.133232091] msec_range[15] 0.050000 - 0.100000 : 17064 [20081021-21:25:42.135149416] msec_range[16] 0.020000 - 0.050000 : 18230 [20081021-21:25:42.137248453] msec_range[17] 0.010000 - 0.020000 : 264 [20081021-21:25:42.139273698] msec_range[18] 0.000000 - 0.010000 : 0 [20081021-21:25:42.141188098] [20081021-21:25:42.143242878] [ close] 0.001000 0.004899 7.754000 115643 [20081021-21:25:42.145215955] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-21:25:42.147267927] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-21:25:42.149346828] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-21:25:42.151292478] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-21:25:42.153403808] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-21:25:42.155443821] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-21:25:42.157461317] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-21:25:42.159588408] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-21:25:42.161813855] msec_range[8] 10.000000 - 20.000000 : 0 [20081021-21:25:42.164369620] msec_range[9] 5.000000 - 10.000000 : 3 [20081021-21:25:42.167454771] msec_range[10] 2.000000 - 5.000000 : 0 [20081021-21:25:42.169855383] msec_range[11] 1.000000 - 2.000000 : 0 [20081021-21:25:42.172314962] msec_range[12] 0.500000 - 1.000000 : 0 [20081021-21:25:42.174805508] msec_range[13] 0.200000 - 0.500000 : 2 [20081021-21:25:42.177021804] msec_range[14] 0.100000 - 0.200000 : 4 [20081021-21:25:42.179513704] msec_range[15] 0.050000 - 0.100000 : 8 [20081021-21:25:42.181768693] msec_range[16] 0.020000 - 0.050000 : 116 [20081021-21:25:42.183940402] msec_range[17] 0.010000 - 0.020000 : 2654 [20081021-21:25:42.186174499] msec_range[18] 0.000000 - 0.010000 : 112856 [20081021-21:25:42.188248072] [20081021-21:25:42.190542667] [20081021-21:25:42.192929314] [20081021-21:25:42.194839003] [20081021-21:25:42.197367944] 1.3% User Time [20081021-21:25:42.199822195] 165.5% System Time [20081021-21:25:42.202211529] 166.7% CPU Utilization [20081021-21:25:42.791885663] Profilers reporting [20081021-21:25:45.969652381] Profilers postprocessing [20081021-21:25:47.187464436] Stopping profiling. [20081021-21:25:47.191488310] Killing daemon. [20081021-21:25:47.574952020] Processing File : /autobench/logs/ffsb.mail_server__threads_0016.08-10-21_21.11.12/analysis/oprofile.001 [20081021-21:25:47.577135882] Processing File : /autobench/logs/ffsb.mail_server__threads_0016.08-10-21_21.11.12/analysis/oprofile-brief.001 [20081021-21:25:47.774867469] Processing File : mpstat.001 [20081021-21:25:47.776902771] Discovered mpstat_interval=[5] [20081021-21:25:48.457394730] Processing Directory : sar.breakout.001 [20081021-21:25:48.459482000] Discovered sar_interval=[5] [20081021-21:25:48.614670765] Processing File : iostat.001 [20081021-21:25:48.616621144] Discovered iostat_interval=[5] [20081021-21:25:53.221144729] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-10-21_1926/btrfs-nodatacow-nodatasum' [20081021-21:26:19.268701190] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081021-21:26:22.181896578] PROCESSING COMMAND : 'mkfs.btrfs /dev/ffsbdev1' [20081021-21:26:22.226261037] fs created label (null) on /dev/ffsbdev1 [20081021-21:26:22.230376335] nodesize 4096 leafsize 4096 sectorsize 4096 size 2.18TB [20081021-21:26:22.232164905] Btrfs v0.16-11-gb431f25 [20081021-21:26:22.291034711] PROCESSING COMMAND : 'mount -t btrfs -o nodatacow,nodatasum /dev/ffsbdev1 /mnt/ffsb1' [20081021-21:26:22.382989065] PROCESSING COMMAND : 'run mail_server__threads_0128 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/mail_server.ffsb num_threads=128' [20081021-21:26:22.426776946] new log requested [20081021-21:26:22.448962524] Running command ffsb [20081021-21:26:33.005662754] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/mail_server.ffsb [20081021-21:26:33.014492013] Importing argument : num_threads=128 [20081021-21:26:33.032435394] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081021-21:26:33.127786352] Checking for sar... [20081021-21:26:33.129867864] found [20081021-21:26:33.185240717] Checking for sar... [20081021-21:26:33.187675744] found [20081021-21:26:33.243310079] Checking for sar... [20081021-21:26:33.245716716] found [20081021-21:26:33.328054538] Checking for gettext... [20081021-21:26:33.340177516] found [20081021-21:26:33.342190527] Checking for libiberty... [20081021-21:26:33.359609968] found [20081021-21:26:33.361297166] Checking for popt... [20081021-21:26:33.369217261] found [20081021-21:26:33.377504804] Checking for popt64... [20081021-21:26:33.379379770] found [20081021-21:26:33.381323244] Checking for oprofile... [20081021-21:26:33.383031660] found [20081021-21:26:33.433525043] opcontrol: oprofile 0.9.3 compiled on Sep 25 2008 09:52:31 [20081021-21:26:33.512044711] Daemon not running [20081021-21:26:33.530196011] Unloading oprofile module [20081021-21:26:33.723129606] Daemon not running [20081021-21:26:34.114166852] Daemon not running [20081021-21:26:34.116493265] Separate options: none [20081021-21:26:34.118414697] vmlinux file: /boot/vmlinux-2.6.27-rc7 [20081021-21:26:34.120247991] Image filter: none [20081021-21:26:34.121992590] Call-graph depth: 0 [20081021-21:26:34.235032279] FFSB version 5.2.1 started [20081021-21:26:34.237036741] [20081021-21:26:34.717688740] benchmark time = 300 [20081021-21:26:34.719798479] ThreadGroup 0 [20081021-21:26:34.721722065] ================ [20081021-21:26:34.723402249] num_threads = 128 [20081021-21:26:34.725532106] [20081021-21:26:34.727652928] read_random = off [20081021-21:26:34.729511133] read_size = 4096 (4KB) [20081021-21:26:34.731351972] read_blocksize = 4096 (4KB) [20081021-21:26:34.733109394] read_skip = off [20081021-21:26:34.735031381] read_skipsize = 0 (0B) [20081021-21:26:34.737148906] [20081021-21:26:34.738980809] write_random = off [20081021-21:26:34.740816594] write_size = 4096 (4KB) [20081021-21:26:34.742547878] fsync_file = 0 [20081021-21:26:34.744310189] write_blocksize = 4096 (4KB) [20081021-21:26:34.746020138] wait time = 0 [20081021-21:26:34.747837971] [20081021-21:26:34.749635189] op weights [20081021-21:26:34.751355411] read = 0 (0.00%) [20081021-21:26:34.753083844] readall = 4 (57.14%) [20081021-21:26:34.754819215] write = 0 (0.00%) [20081021-21:26:34.756573418] create = 2 (28.57%) [20081021-21:26:34.758293656] append = 0 (0.00%) [20081021-21:26:34.760104581] delete = 1 (14.29%) [20081021-21:26:34.761929656] metaop = 0 (0.00%) [20081021-21:26:34.763641357] createdir = 0 (0.00%) [20081021-21:26:34.765440646] stat = 0 (0.00%) [20081021-21:26:34.767082520] writeall = 0 (0.00%) [20081021-21:26:34.768895346] writeall_fsync = 0 (0.00%) [20081021-21:26:34.770586013] open_close = 0 (0.00%) [20081021-21:26:34.772381060] [20081021-21:26:34.774119801] FileSystem /mnt/ffsb1 [20081021-21:26:34.775874508] ========== [20081021-21:26:34.777662611] num_dirs = 1000 [20081021-21:26:34.779377385] starting files = 1000000 [20081021-21:26:34.781116664] [20081021-21:26:34.782868730] min file size = 0 (0B) [20081021-21:26:34.784661465] max file size = 0 (0B) [20081021-21:26:34.786533306] directio = off [20081021-21:26:34.788236898] alignedio = on [20081021-21:26:34.790035707] bufferedio = off [20081021-21:26:34.791759269] [20081021-21:26:34.793526877] aging is off [20081021-21:26:34.795215469] current utilization = 0.00% [20081021-21:26:34.797041993] [20081021-21:26:34.798834440] creating new fileset /mnt/ffsb1 [20081021-21:34:53.793532654] fs setup took 498 secs [20081021-21:34:54.247693641] Syncing()...0 sec [20081021-21:34:54.255228498] Starting Actual Benchmark At: Tue Oct 21 21:34:54 2008 [20081021-21:34:54.288319621] [20081021-21:41:15.927055342] Syncing()...80 sec [20081021-21:41:15.945880402] FFSB benchmark finished at: Tue Oct 21 21:41:15 2008 [20081021-21:41:15.948691783] [20081021-21:41:15.951163257] Results: [20081021-21:41:15.977775329] Benchmark took 381.52 sec [20081021-21:41:15.980249137] [20081021-21:41:15.982344546] Total Results [20081021-21:41:15.996362975] =============== [20081021-21:41:15.998590926] readall : 1034032 ops (66.245332%) [20081021-21:41:16.000754770] create : 507930 ops (32.540571%) [20081021-21:41:16.002788439] delete : 18951 ops (1.214097%) [20081021-21:41:16.004835524] 4091.25 Transactions per Second [20081021-21:41:16.006895483] [20081021-21:41:16.008838894] System Call Latency statistics in millisecs [20081021-21:41:16.011399755] ===== [20081021-21:41:16.013654189] Min Avg Max Total Calls [20081021-21:41:16.016021775] ======== ======== ======== ============ [20081021-21:41:16.018110687] [ open] 0.009000 11.469413 1586.212036 115524 [20081021-21:41:16.043095021] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-21:41:16.045201830] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-21:41:16.047198152] msec_range[2] 1000.000000 - 2000.000000 : 2 [20081021-21:41:16.049326786] msec_range[3] 500.000000 - 1000.000000 : 17 [20081021-21:41:16.051364798] msec_range[4] 200.000000 - 500.000000 : 175 [20081021-21:41:16.053442863] msec_range[5] 100.000000 - 200.000000 : 659 [20081021-21:41:16.055415479] msec_range[6] 50.000000 - 100.000000 : 3269 [20081021-21:41:16.057528340] msec_range[7] 20.000000 - 50.000000 : 13320 [20081021-21:41:16.059662575] msec_range[8] 10.000000 - 20.000000 : 22682 [20081021-21:41:16.061634558] msec_range[9] 5.000000 - 10.000000 : 23450 [20081021-21:41:16.063784110] msec_range[10] 2.000000 - 5.000000 : 14900 [20081021-21:41:16.065765998] msec_range[11] 1.000000 - 2.000000 : 4451 [20081021-21:41:16.067796516] msec_range[12] 0.500000 - 1.000000 : 3076 [20081021-21:41:16.069799074] msec_range[13] 0.200000 - 0.500000 : 5980 [20081021-21:41:16.072127975] msec_range[14] 0.100000 - 0.200000 : 13407 [20081021-21:41:16.074349994] msec_range[15] 0.050000 - 0.100000 : 8031 [20081021-21:41:16.076467638] msec_range[16] 0.020000 - 0.050000 : 724 [20081021-21:41:16.078695527] msec_range[17] 0.010000 - 0.020000 : 1371 [20081021-21:41:16.080756293] msec_range[18] 0.000000 - 0.010000 : 10 [20081021-21:41:16.082859133] [20081021-21:41:16.084884986] [ read] 0.004000 3.460620 1509.345947 1048747 [20081021-21:41:16.087028109] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-21:41:16.089110614] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-21:41:16.091053305] msec_range[2] 1000.000000 - 2000.000000 : 32 [20081021-21:41:16.093137428] msec_range[3] 500.000000 - 1000.000000 : 99 [20081021-21:41:16.095115500] msec_range[4] 200.000000 - 500.000000 : 527 [20081021-21:41:16.097138620] msec_range[5] 100.000000 - 200.000000 : 2812 [20081021-21:41:16.099120366] msec_range[6] 50.000000 - 100.000000 : 14200 [20081021-21:41:16.101220392] msec_range[7] 20.000000 - 50.000000 : 42810 [20081021-21:41:16.103336431] msec_range[8] 10.000000 - 20.000000 : 26968 [20081021-21:41:16.105510489] msec_range[9] 5.000000 - 10.000000 : 26074 [20081021-21:41:16.107659917] msec_range[10] 2.000000 - 5.000000 : 18182 [20081021-21:41:16.109663906] msec_range[11] 1.000000 - 2.000000 : 6681 [20081021-21:41:16.111712025] msec_range[12] 0.500000 - 1.000000 : 9149 [20081021-21:41:16.113740939] msec_range[13] 0.200000 - 0.500000 : 4642 [20081021-21:41:16.115840707] msec_range[14] 0.100000 - 0.200000 : 13015 [20081021-21:41:16.117907523] msec_range[15] 0.050000 - 0.100000 : 28952 [20081021-21:41:16.119959521] msec_range[16] 0.020000 - 0.050000 : 34855 [20081021-21:41:16.122039564] msec_range[17] 0.010000 - 0.020000 : 44392 [20081021-21:41:16.124030268] msec_range[18] 0.000000 - 0.010000 : 775357 [20081021-21:41:16.126052261] [20081021-21:41:16.128368550] [ write] 0.019000 8.359128 1001.994019 507930 [20081021-21:41:16.130466049] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-21:41:16.132777213] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-21:41:16.135249362] msec_range[2] 1000.000000 - 2000.000000 : 4 [20081021-21:41:16.137415840] msec_range[3] 500.000000 - 1000.000000 : 57 [20081021-21:41:16.139585300] msec_range[4] 200.000000 - 500.000000 : 458 [20081021-21:41:16.141958598] msec_range[5] 100.000000 - 200.000000 : 1415 [20081021-21:41:16.144354731] msec_range[6] 50.000000 - 100.000000 : 10522 [20081021-21:41:16.146646062] msec_range[7] 20.000000 - 50.000000 : 34183 [20081021-21:41:16.148826579] msec_range[8] 10.000000 - 20.000000 : 65814 [20081021-21:41:16.151116509] msec_range[9] 5.000000 - 10.000000 : 107809 [20081021-21:41:16.153577917] msec_range[10] 2.000000 - 5.000000 : 96110 [20081021-21:41:16.155626618] msec_range[11] 1.000000 - 2.000000 : 51896 [20081021-21:41:16.157719542] msec_range[12] 0.500000 - 1.000000 : 35277 [20081021-21:41:16.159997408] msec_range[13] 0.200000 - 0.500000 : 26884 [20081021-21:41:16.162132737] msec_range[14] 0.100000 - 0.200000 : 36525 [20081021-21:41:16.164203986] msec_range[15] 0.050000 - 0.100000 : 26851 [20081021-21:41:16.166558675] msec_range[16] 0.020000 - 0.050000 : 14090 [20081021-21:41:16.168713967] msec_range[17] 0.010000 - 0.020000 : 35 [20081021-21:41:16.170815225] msec_range[18] 0.000000 - 0.010000 : 0 [20081021-21:41:16.172764670] [20081021-21:41:16.174856452] [ close] 0.001000 0.005743 6.847000 115524 [20081021-21:41:16.176952005] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081021-21:41:16.178881846] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081021-21:41:16.180959435] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081021-21:41:16.182969997] msec_range[3] 500.000000 - 1000.000000 : 0 [20081021-21:41:16.185007972] msec_range[4] 200.000000 - 500.000000 : 0 [20081021-21:41:16.186971815] msec_range[5] 100.000000 - 200.000000 : 0 [20081021-21:41:16.189035384] msec_range[6] 50.000000 - 100.000000 : 0 [20081021-21:41:16.191095586] msec_range[7] 20.000000 - 50.000000 : 0 [20081021-21:41:16.193034503] msec_range[8] 10.000000 - 20.000000 : 0 [20081021-21:41:16.195082216] msec_range[9] 5.000000 - 10.000000 : 5 [20081021-21:41:16.197021895] msec_range[10] 2.000000 - 5.000000 : 2 [20081021-21:41:16.199121524] msec_range[11] 1.000000 - 2.000000 : 3 [20081021-21:41:16.201142947] msec_range[12] 0.500000 - 1.000000 : 8 [20081021-21:41:16.203262913] msec_range[13] 0.200000 - 0.500000 : 37 [20081021-21:41:16.205308251] msec_range[14] 0.100000 - 0.200000 : 32 [20081021-21:41:16.207230600] msec_range[15] 0.050000 - 0.100000 : 52 [20081021-21:41:16.209286852] msec_range[16] 0.020000 - 0.050000 : 206 [20081021-21:41:16.211302232] msec_range[17] 0.010000 - 0.020000 : 4187 [20081021-21:41:16.213235026] msec_range[18] 0.000000 - 0.010000 : 110992 [20081021-21:41:16.215321475] [20081021-21:41:16.217334619] [20081021-21:41:16.219265379] [20081021-21:41:16.221353778] [20081021-21:41:16.223566686] 2.0% User Time [20081021-21:41:16.225715888] 251.1% System Time [20081021-21:41:16.228041685] 253.1% CPU Utilization [20081021-21:41:17.161529510] Profilers reporting [20081021-21:41:20.129724669] Profilers postprocessing [20081021-21:41:21.353494976] Stopping profiling. [20081021-21:41:21.358559671] Killing daemon. [20081021-21:41:22.739893291] Processing File : /autobench/logs/ffsb.mail_server__threads_0128.08-10-21_21.26.22/analysis/oprofile.001 [20081021-21:41:22.742259256] Processing File : /autobench/logs/ffsb.mail_server__threads_0128.08-10-21_21.26.22/analysis/oprofile-brief.001 [20081021-21:41:22.935611461] Processing File : mpstat.001 [20081021-21:41:22.937647056] Discovered mpstat_interval=[5] [20081021-21:41:23.569317213] Processing Directory : sar.breakout.001 [20081021-21:41:23.571599571] Discovered sar_interval=[5] [20081021-21:41:23.727670039] Processing File : iostat.001 [20081021-21:41:23.729868835] Discovered iostat_interval=[5] [20081021-21:41:25.168304928] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-10-21_1926/btrfs-nodatacow-nodatasum'