[20091112-13:21:57.258144724] PROCESSING COMMAND : 'clearprofilers' [20091112-13:21:57.569398825] PROCESSING COMMAND : 'useprofiler iostat 5' [20091112-13:21:57.695285256] Checking for sar... [20091112-13:21:57.697711796] found [20091112-13:21:57.857095185] PROCESSING COMMAND : 'useprofiler sar 5' [20091112-13:21:57.981424387] Checking for sar... [20091112-13:21:57.984035144] found [20091112-13:21:58.142587701] PROCESSING COMMAND : 'useprofiler mpstat 5' [20091112-13:21:58.268737416] Checking for sar... [20091112-13:21:58.271160964] found [20091112-13:21:58.465911166] PROCESSING COMMAND : 'useprofiler oprofile' [20091112-13:21:58.641910391] Checking for gettext... [20091112-13:21:58.649601401] found [20091112-13:21:58.651548226] Checking for libiberty in autobench... [20091112-13:21:58.677610769] found [20091112-13:21:58.687538553] Checking for popt64... [20091112-13:21:58.689562263] found [20091112-13:21:58.691518340] Checking for oprofile... [20091112-13:21:58.714886826] found [20091112-13:21:58.784893060] opcontrol: oprofile 0.9.5-rc2 compiled on Sep 16 2009 11:04:31 [20091112-13:21:59.008479084] dump fail: daemon died during last run ? [20091112-13:21:59.013226240] Detected stale lock file. Removing. [20091112-13:22:04.393376684] OPROFILE : using callgraph [5] [20091112-13:22:04.643616783] Daemon not running [20091112-13:22:04.645913974] Separate options: none [20091112-13:22:04.647968502] vmlinux file: /boot/vmlinux-2.6.31-autokern1 [20091112-13:22:04.649976901] Image filter: none [20091112-13:22:04.651882863] Call-graph depth: 5 [20091112-13:22:04.886156514] PROCESSING COMMAND : 'umount /mnt/ffsb1 > /dev/null 2>&1' [20091112-13:22:04.963439382] PROCESSING COMMAND : 'set-sched noop' [20091112-13:22:05.309470905] PROCESSING COMMAND : 'mkresultdirs hks.austin.ibm.com benchmarks/results/btrfs/ffsb btrfs2 2009-11-12_1321 btrfs11-12' [20091112-13:22:05.525100710] Connecting to hks.austin.ibm.com... [20091112-13:22:05.527170244] Remote working directory: /opt [20091112-13:22:05.529208783] Remote working directory: /opt/benchmarks/results/btrfs/ffsb [20091112-13:22:05.531706668] Couldn't create directory: Failure [20091112-13:22:05.533736887] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs2 [20091112-13:22:05.535889298] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs2 [20091112-13:22:05.537776446] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs2/2009-11-12_1321 [20091112-13:22:05.539899851] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs2/2009-11-12_1321 [20091112-13:22:05.541961403] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs2/2009-11-12_1321/btrfs11-12 [20091112-13:22:05.618193127] PROCESSING COMMAND : 'mkfs.btrfs -V 2>&1' [20091112-13:22:05.655464522] mkfs.btrfs: invalid option -- V [20091112-13:22:05.657730308] usage: mkfs.btrfs [options] dev [ dev ... ] [20091112-13:22:05.659770645] options: [20091112-13:22:05.661884723] -A --alloc-start the offset to start the FS [20091112-13:22:05.666607643] -b --byte-count total number of bytes in the FS [20091112-13:22:05.669047317] -d --data data profile, raid0, raid1, raid10 or single [20091112-13:22:05.671065262] -l --leafsize size of btree leaves [20091112-13:22:05.672991559] -L --label set a label [20091112-13:22:05.675148734] -m --metadata metadata profile, values like data profile [20091112-13:22:05.677107443] -n --nodesize size of btree nodes [20091112-13:22:05.679044026] -s --sectorsize min block allocation [20091112-13:22:05.683979611] Btrfs v0.18-13-gb8420fa [20091112-13:22:05.760045241] PROCESSING COMMAND : 'mkfs.btrfs /dev/ffsbdev1' [20091112-13:22:05.798446821] [20091112-13:22:05.800524018] WARNING! - Btrfs v0.18-13-gb8420fa IS EXPERIMENTAL [20091112-13:22:05.802434980] WARNING! - see http://btrfs.wiki.kernel.org before using [20091112-13:22:05.804364065] [20091112-13:22:05.806281820] fs created label (null) on /dev/ffsbdev1 [20091112-13:22:05.808222244] nodesize 4096 leafsize 4096 sectorsize 4096 size 68.37GB [20091112-13:22:05.810104271] Btrfs v0.18-13-gb8420fa [20091112-13:22:06.055679684] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20091112-13:22:06.349278431] PROCESSING COMMAND : 'run sequential_reads__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb num_threads=1' [20091112-13:22:06.406047708] new log requested [20091112-13:22:06.443468886] Running command ffsb [20091112-13:22:18.953175336] 11/12/2009-13:22:18 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb Succeeded [20091112-13:22:18.964456342] Importing argument : num_threads=1 [20091112-13:22:18.993240678] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20091112-13:22:19.112889490] FFSB version 6.0-RC2.1 started [20091112-13:22:19.115308646] [20091112-13:22:19.117394737] benchmark time = 300 [20091112-13:22:19.119355923] ThreadGroup 0 [20091112-13:22:19.121644482] ================ [20091112-13:22:19.123638095] num_threads = 1 [20091112-13:22:19.125566829] [20091112-13:22:19.127567427] read_random = off [20091112-13:22:19.129612550] read_size = 0 (0B) [20091112-13:22:19.131583389] read_blocksize = 4096 (4KB) [20091112-13:22:19.133642122] read_skip = off [20091112-13:22:19.135677196] read_skipsize = 0 (0B) [20091112-13:22:19.137696765] [20091112-13:22:19.139758285] write_random = off [20091112-13:22:19.141760511] write_size = 0 (0B) [20091112-13:22:19.143773967] fsync_file = 0 [20091112-13:22:19.145878479] write_blocksize = 0 (0B) [20091112-13:22:19.147886017] wait time = 0 [20091112-13:22:19.149946229] [20091112-13:22:19.152146016] op weights [20091112-13:22:19.154237521] read = 0 (0.00%) [20091112-13:22:19.156294723] readall = 1 (100.00%) [20091112-13:22:19.158361657] write = 0 (0.00%) [20091112-13:22:19.160414016] create = 0 (0.00%) [20091112-13:22:19.162451949] append = 0 (0.00%) [20091112-13:22:19.164450335] delete = 0 (0.00%) [20091112-13:22:19.166527096] metaop = 0 (0.00%) [20091112-13:22:19.168515675] createdir = 0 (0.00%) [20091112-13:22:19.170556635] stat = 0 (0.00%) [20091112-13:22:19.172664637] writeall = 0 (0.00%) [20091112-13:22:19.174680564] writeall_fsync = 0 (0.00%) [20091112-13:22:19.176699415] open_close = 0 (0.00%) [20091112-13:22:19.178762945] write_fsync = 0 (0.00%) [20091112-13:22:19.180784731] create_fsync = 0 (0.00%) [20091112-13:22:19.182977853] append_fsync = 0 (0.00%) [20091112-13:22:19.185037073] [20091112-13:22:19.187105345] FileSystem /mnt/ffsb1 [20091112-13:22:19.189122083] ========== [20091112-13:22:19.191219944] num_dirs = 0 [20091112-13:22:19.193217089] starting files = 1024 [20091112-13:22:19.195317981] [20091112-13:22:19.197340195] min file size = 36700160 (35MB) [20091112-13:22:19.199428187] max file size = 36700160 (35MB) [20091112-13:22:19.201490369] directio = off [20091112-13:22:19.203462436] alignedio = on [20091112-13:22:19.205485149] bufferedio = off [20091112-13:22:19.207554151] [20091112-13:22:19.209629266] aging is off [20091112-13:22:19.211683029] current utilization = 0.00% [20091112-13:22:19.213729399] [20091112-13:22:19.215756572] checking existing fs: /mnt/ffsb1 [20091112-13:22:19.217812859] opendir: No such file or directory [20091112-13:22:19.219858251] recreating new fileset [20091112-13:28:24.501417811] fs setup took 365 secs [20091112-13:28:31.938111105] Syncing()...7 sec [20091112-13:28:31.940084922] Starting Actual Benchmark At: Thu Nov 12 13:28:31 2009 [20091112-13:28:31.974027111] [20091112-13:33:34.636280237] Syncing()...1 sec [20091112-13:33:34.676248062] FFSB benchmark finished at: Thu Nov 12 13:33:34 2009 [20091112-13:33:34.679028752] [20091112-13:33:34.682069678] Results: [20091112-13:33:34.731733406] Benchmark took 302.42 sec [20091112-13:33:34.734680513] [20091112-13:33:34.737369497] Total Results [20091112-13:33:34.755821078] =============== [20091112-13:33:34.758638403] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20091112-13:33:34.761458149] ======= ============ ========= ======= =========== ========== [20091112-13:33:34.763900524] readall : 7822080 25865.03 100.000% 100.000% 101MB/sec [20091112-13:33:34.766497304] - [20091112-13:33:34.769153192] 25865.03 Transactions per Second [20091112-13:33:34.771764591] [20091112-13:33:34.774444778] Throughput Results [20091112-13:33:34.793463557] =================== [20091112-13:33:34.796217891] Read Throughput: 101MB/sec [20091112-13:33:34.798886390] [20091112-13:33:34.804115612] System Call Latency statistics in millisecs [20091112-13:33:34.806827422] ===== [20091112-13:33:34.809346096] Min Avg Max Total Calls [20091112-13:33:34.811852156] ======== ======== ======== ============ [20091112-13:33:34.814365565] [ open] 0.015000 0.123073 15.557000 873 [20091112-13:33:34.816802065] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091112-13:33:34.819382634] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091112-13:33:34.821946765] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091112-13:33:34.824750271] msec_range[3] 500.000000 - 1000.000000 : 0 [20091112-13:33:34.829622259] msec_range[4] 200.000000 - 500.000000 : 0 [20091112-13:33:34.832541278] msec_range[5] 100.000000 - 200.000000 : 0 [20091112-13:33:34.836947277] msec_range[6] 50.000000 - 100.000000 : 0 [20091112-13:33:34.840104381] msec_range[7] 20.000000 - 50.000000 : 0 [20091112-13:33:34.843464257] msec_range[8] 10.000000 - 20.000000 : 3 [20091112-13:33:34.846640039] msec_range[9] 5.000000 - 10.000000 : 2 [20091112-13:33:34.849987323] msec_range[10] 2.000000 - 5.000000 : 2 [20091112-13:33:34.852921742] msec_range[11] 1.000000 - 2.000000 : 0 [20091112-13:33:34.855753127] msec_range[12] 0.500000 - 1.000000 : 0 [20091112-13:33:34.858348587] msec_range[13] 0.200000 - 0.500000 : 0 [20091112-13:33:34.861036901] msec_range[14] 0.100000 - 0.200000 : 10 [20091112-13:33:34.863779557] msec_range[15] 0.050000 - 0.100000 : 545 [20091112-13:33:34.866466175] msec_range[16] 0.020000 - 0.050000 : 310 [20091112-13:33:34.868995318] msec_range[17] 0.010000 - 0.020000 : 1 [20091112-13:33:34.871619566] msec_range[18] 0.000000 - 0.010000 : 0 [20091112-13:33:34.874251093] [20091112-13:33:34.876924434] [ read] 0.001000 0.038199 92.366997 7822080 [20091112-13:33:34.879482913] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091112-13:33:34.882093962] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091112-13:33:34.884667391] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091112-13:33:34.887337924] msec_range[3] 500.000000 - 1000.000000 : 0 [20091112-13:33:34.890212382] msec_range[4] 200.000000 - 500.000000 : 0 [20091112-13:33:34.893145848] msec_range[5] 100.000000 - 200.000000 : 0 [20091112-13:33:34.896229127] msec_range[6] 50.000000 - 100.000000 : 45 [20091112-13:33:34.899013719] msec_range[7] 20.000000 - 50.000000 : 94 [20091112-13:33:34.901878150] msec_range[8] 10.000000 - 20.000000 : 227 [20091112-13:33:34.904525025] msec_range[9] 5.000000 - 10.000000 : 8344 [20091112-13:33:34.907329106] msec_range[10] 2.000000 - 5.000000 : 46432 [20091112-13:33:34.910125141] msec_range[11] 1.000000 - 2.000000 : 1088 [20091112-13:33:34.913140691] msec_range[12] 0.500000 - 1.000000 : 111 [20091112-13:33:34.918548735] msec_range[13] 0.200000 - 0.500000 : 452 [20091112-13:33:34.922010126] msec_range[14] 0.100000 - 0.200000 : 384 [20091112-13:33:34.925088638] msec_range[15] 0.050000 - 0.100000 : 931 [20091112-13:33:34.928386804] msec_range[16] 0.020000 - 0.050000 : 848 [20091112-13:33:34.931148245] msec_range[17] 0.010000 - 0.020000 : 91571 [20091112-13:33:34.934542955] msec_range[18] 0.000000 - 0.010000 : 7671553 [20091112-13:33:34.938113061] [20091112-13:33:34.942067712] [ close] 0.004000 0.007589 0.029000 873 [20091112-13:33:34.946042373] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091112-13:33:34.949698511] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091112-13:33:34.952976486] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091112-13:33:34.955845847] msec_range[3] 500.000000 - 1000.000000 : 0 [20091112-13:33:34.958967062] msec_range[4] 200.000000 - 500.000000 : 0 [20091112-13:33:34.962078967] msec_range[5] 100.000000 - 200.000000 : 0 [20091112-13:33:34.965037631] msec_range[6] 50.000000 - 100.000000 : 0 [20091112-13:33:34.967991599] msec_range[7] 20.000000 - 50.000000 : 0 [20091112-13:33:34.970958185] msec_range[8] 10.000000 - 20.000000 : 0 [20091112-13:33:34.973940462] msec_range[9] 5.000000 - 10.000000 : 0 [20091112-13:33:34.976642111] msec_range[10] 2.000000 - 5.000000 : 0 [20091112-13:33:34.979416989] msec_range[11] 1.000000 - 2.000000 : 0 [20091112-13:33:34.982161893] msec_range[12] 0.500000 - 1.000000 : 0 [20091112-13:33:34.984981820] msec_range[13] 0.200000 - 0.500000 : 0 [20091112-13:33:34.987676567] msec_range[14] 0.100000 - 0.200000 : 0 [20091112-13:33:34.990345699] msec_range[15] 0.050000 - 0.100000 : 0 [20091112-13:33:34.993858209] msec_range[16] 0.020000 - 0.050000 : 1 [20091112-13:33:34.996837039] msec_range[17] 0.010000 - 0.020000 : 32 [20091112-13:33:34.999708928] msec_range[18] 0.000000 - 0.010000 : 840 [20091112-13:33:35.002541251] [20091112-13:33:35.005573078] [20091112-13:33:35.008977268] [20091112-13:33:35.012109650] [20091112-13:33:35.015372973] 1.4% User Time [20091112-13:33:35.018263336] 20.5% System Time [20091112-13:33:35.020988325] 21.9% CPU Utilization [20091112-13:33:35.023735979] Profilers reporting [20091112-13:33:52.986402862] Profilers postprocessing [20091112-13:33:53.250541661] Processing File : iostat.001 [20091112-13:33:53.252876987] Discovered iostat_interval=[5] [20091112-13:33:54.002016819] Processing Directory : sar.breakout.001 [20091112-13:33:54.004147179] Discovered sar_interval=[5] [20091112-13:33:54.175231480] Processing File : mpstat.001 [20091112-13:33:54.177452391] Discovered mpstat_interval=[5] [20091112-13:33:55.324977707] Stopping profiling. [20091112-13:33:55.331966688] Killing daemon. [20091112-13:33:57.632853701] Processing File : oprofile.001 [20091112-13:33:57.635153045] Processing File : oprofile-brief.001 [20091112-13:33:59.106065579] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-11-12_1321/btrfs11-12' [20091112-13:34:01.787612683] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20091112-13:34:04.102032861] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20091112-13:34:04.264699704] PROCESSING COMMAND : 'run sequential_reads__threads_0008 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb num_threads=8' [20091112-13:34:04.313718076] new log requested [20091112-13:34:04.358946932] Running command ffsb [20091112-13:34:15.662912270] 11/12/2009-13:34:15 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb Succeeded [20091112-13:34:15.674166046] Importing argument : num_threads=8 [20091112-13:34:15.704144480] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20091112-13:34:15.785324298] FFSB version 6.0-RC2.1 started [20091112-13:34:15.787662488] [20091112-13:34:15.819761688] benchmark time = 300 [20091112-13:34:15.822048698] ThreadGroup 0 [20091112-13:34:15.824199431] ================ [20091112-13:34:15.826308673] num_threads = 8 [20091112-13:34:15.828328165] [20091112-13:34:15.830258218] read_random = off [20091112-13:34:15.832211932] read_size = 0 (0B) [20091112-13:34:15.834182945] read_blocksize = 4096 (4KB) [20091112-13:34:15.836190982] read_skip = off [20091112-13:34:15.838083146] read_skipsize = 0 (0B) [20091112-13:34:15.840022274] [20091112-13:34:15.841910832] write_random = off [20091112-13:34:15.843865110] write_size = 0 (0B) [20091112-13:34:15.845819001] fsync_file = 0 [20091112-13:34:15.847726050] write_blocksize = 0 (0B) [20091112-13:34:15.849603409] wait time = 0 [20091112-13:34:15.851541998] [20091112-13:34:15.853451536] op weights [20091112-13:34:15.855389753] read = 0 (0.00%) [20091112-13:34:15.857263923] readall = 1 (100.00%) [20091112-13:34:15.859226910] write = 0 (0.00%) [20091112-13:34:15.861113330] create = 0 (0.00%) [20091112-13:34:15.863045985] append = 0 (0.00%) [20091112-13:34:15.864914623] delete = 0 (0.00%) [20091112-13:34:15.866851096] metaop = 0 (0.00%) [20091112-13:34:15.868922586] createdir = 0 (0.00%) [20091112-13:34:15.870833539] stat = 0 (0.00%) [20091112-13:34:15.872751705] writeall = 0 (0.00%) [20091112-13:34:15.874708987] writeall_fsync = 0 (0.00%) [20091112-13:34:15.876643295] open_close = 0 (0.00%) [20091112-13:34:15.878581998] write_fsync = 0 (0.00%) [20091112-13:34:15.880478569] create_fsync = 0 (0.00%) [20091112-13:34:15.882407495] append_fsync = 0 (0.00%) [20091112-13:34:15.884310607] [20091112-13:34:15.886246022] FileSystem /mnt/ffsb1 [20091112-13:34:15.888097888] ========== [20091112-13:34:15.890200835] num_dirs = 0 [20091112-13:34:15.892074786] starting files = 1024 [20091112-13:34:15.894001550] [20091112-13:34:15.895927256] min file size = 36700160 (35MB) [20091112-13:34:15.897878560] max file size = 36700160 (35MB) [20091112-13:34:15.899845538] directio = off [20091112-13:34:15.901759585] alignedio = on [20091112-13:34:15.903660110] bufferedio = off [20091112-13:34:15.905608737] [20091112-13:34:15.907497537] aging is off [20091112-13:34:15.909436200] current utilization = 51.27% [20091112-13:34:15.911345288] [20091112-13:34:15.913314488] checking existing fs: /mnt/ffsb1 [20091112-13:34:16.480491779] fs setup took 0 secs [20091112-13:34:17.088595520] Syncing()...0 sec [20091112-13:34:17.090842116] Starting Actual Benchmark At: Thu Nov 12 13:34:17 2009 [20091112-13:34:17.105651885] [20091112-13:39:20.749112634] Syncing()...0 sec [20091112-13:39:20.793472577] FFSB benchmark finished at: Thu Nov 12 13:39:20 2009 [20091112-13:39:20.796874891] [20091112-13:39:20.800264732] Results: [20091112-13:39:20.889118270] Benchmark took 303.26 sec [20091112-13:39:20.892023065] [20091112-13:39:20.894988403] Total Results [20091112-13:39:20.914409724] =============== [20091112-13:39:20.916914766] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20091112-13:39:20.919868385] ======= ============ ========= ======= =========== ========== [20091112-13:39:20.922832872] readall : 7562240 24936.40 100.000% 100.000% 97.4MB/sec [20091112-13:39:20.925837298] - [20091112-13:39:20.928700865] 24936.40 Transactions per Second [20091112-13:39:20.931489651] [20091112-13:39:20.933983823] Throughput Results [20091112-13:39:20.952711188] =================== [20091112-13:39:20.955847464] Read Throughput: 97.4MB/sec [20091112-13:39:20.959571869] [20091112-13:39:20.962271722] System Call Latency statistics in millisecs [20091112-13:39:20.964853335] ===== [20091112-13:39:20.968704208] Min Avg Max Total Calls [20091112-13:39:20.971343386] ======== ======== ======== ============ [20091112-13:39:20.974484964] [ open] 0.007000 4.346469 598.385010 844 [20091112-13:39:20.977225735] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091112-13:39:20.979861079] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091112-13:39:20.982806132] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091112-13:39:20.986536400] msec_range[3] 500.000000 - 1000.000000 : 2 [20091112-13:39:20.988953365] msec_range[4] 200.000000 - 500.000000 : 4 [20091112-13:39:20.991422951] msec_range[5] 100.000000 - 200.000000 : 6 [20091112-13:39:20.994105371] msec_range[6] 50.000000 - 100.000000 : 4 [20091112-13:39:20.996994568] msec_range[7] 20.000000 - 50.000000 : 0 [20091112-13:39:20.999434773] msec_range[8] 10.000000 - 20.000000 : 1 [20091112-13:39:21.001823656] msec_range[9] 5.000000 - 10.000000 : 0 [20091112-13:39:21.006912455] msec_range[10] 2.000000 - 5.000000 : 0 [20091112-13:39:21.009525440] msec_range[11] 1.000000 - 2.000000 : 0 [20091112-13:39:21.012347173] msec_range[12] 0.500000 - 1.000000 : 0 [20091112-13:39:21.015043867] msec_range[13] 0.200000 - 0.500000 : 0 [20091112-13:39:21.017591962] msec_range[14] 0.100000 - 0.200000 : 100 [20091112-13:39:21.020201704] msec_range[15] 0.050000 - 0.100000 : 387 [20091112-13:39:21.022880810] msec_range[16] 0.020000 - 0.050000 : 331 [20091112-13:39:21.025770645] msec_range[17] 0.010000 - 0.020000 : 4 [20091112-13:39:21.028783252] msec_range[18] 0.000000 - 0.010000 : 5 [20091112-13:39:21.031606610] [20091112-13:39:21.034195948] [ read] 0.001000 0.318079 2959.844971 7562240 [20091112-13:39:21.036588955] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091112-13:39:21.039492146] msec_range[1] 2000.000000 - 5000.000000 : 69 [20091112-13:39:21.042426344] msec_range[2] 1000.000000 - 2000.000000 : 351 [20091112-13:39:21.045621358] msec_range[3] 500.000000 - 1000.000000 : 498 [20091112-13:39:21.049304503] msec_range[4] 200.000000 - 500.000000 : 2426 [20091112-13:39:21.052099152] msec_range[5] 100.000000 - 200.000000 : 1775 [20091112-13:39:21.054769498] msec_range[6] 50.000000 - 100.000000 : 1072 [20091112-13:39:21.058224949] msec_range[7] 20.000000 - 50.000000 : 978 [20091112-13:39:21.061252260] msec_range[8] 10.000000 - 20.000000 : 437 [20091112-13:39:21.064089417] msec_range[9] 5.000000 - 10.000000 : 5248 [20091112-13:39:21.066856880] msec_range[10] 2.000000 - 5.000000 : 36428 [20091112-13:39:21.069806384] msec_range[11] 1.000000 - 2.000000 : 1585 [20091112-13:39:21.073077980] msec_range[12] 0.500000 - 1.000000 : 217 [20091112-13:39:21.076348522] msec_range[13] 0.200000 - 0.500000 : 242 [20091112-13:39:21.080765648] msec_range[14] 0.100000 - 0.200000 : 754 [20091112-13:39:21.084722699] msec_range[15] 0.050000 - 0.100000 : 407 [20091112-13:39:21.087547541] msec_range[16] 0.020000 - 0.050000 : 10214 [20091112-13:39:21.090353839] msec_range[17] 0.010000 - 0.020000 : 839656 [20091112-13:39:21.093084626] msec_range[18] 0.000000 - 0.010000 : 6659883 [20091112-13:39:21.095946801] [20091112-13:39:21.099198506] [ close] 0.004000 0.009236 0.022000 844 [20091112-13:39:21.101549682] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091112-13:39:21.104133242] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091112-13:39:21.106813333] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091112-13:39:21.109188170] msec_range[3] 500.000000 - 1000.000000 : 0 [20091112-13:39:21.111490758] msec_range[4] 200.000000 - 500.000000 : 0 [20091112-13:39:21.114076141] msec_range[5] 100.000000 - 200.000000 : 0 [20091112-13:39:21.116741020] msec_range[6] 50.000000 - 100.000000 : 0 [20091112-13:39:21.119139204] msec_range[7] 20.000000 - 50.000000 : 0 [20091112-13:39:21.121494277] msec_range[8] 10.000000 - 20.000000 : 0 [20091112-13:39:21.124155254] msec_range[9] 5.000000 - 10.000000 : 0 [20091112-13:39:21.126972917] msec_range[10] 2.000000 - 5.000000 : 0 [20091112-13:39:21.129412493] msec_range[11] 1.000000 - 2.000000 : 0 [20091112-13:39:21.131786464] msec_range[12] 0.500000 - 1.000000 : 0 [20091112-13:39:21.134587400] msec_range[13] 0.200000 - 0.500000 : 0 [20091112-13:39:21.137648240] msec_range[14] 0.100000 - 0.200000 : 0 [20091112-13:39:21.140114543] msec_range[15] 0.050000 - 0.100000 : 0 [20091112-13:39:21.142449670] msec_range[16] 0.020000 - 0.050000 : 1 [20091112-13:39:21.145222766] msec_range[17] 0.010000 - 0.020000 : 205 [20091112-13:39:21.148096070] msec_range[18] 0.000000 - 0.010000 : 638 [20091112-13:39:21.150549364] [20091112-13:39:21.153062272] [20091112-13:39:21.155812290] [20091112-13:39:21.158699688] [20091112-13:39:21.161185050] 1.5% User Time [20091112-13:39:21.163525395] 23.3% System Time [20091112-13:39:21.166138124] 24.7% CPU Utilization [20091112-13:39:21.168814276] Profilers reporting [20091112-13:39:52.491638794] Profilers postprocessing [20091112-13:39:52.767819897] Processing File : iostat.001 [20091112-13:39:52.770051541] Discovered iostat_interval=[5] [20091112-13:39:53.536835451] Processing Directory : sar.breakout.001 [20091112-13:39:53.539277215] Discovered sar_interval=[5] [20091112-13:39:53.719520169] Processing File : mpstat.001 [20091112-13:39:53.721769017] Discovered mpstat_interval=[5] [20091112-13:39:54.868898627] Stopping profiling. [20091112-13:39:54.875686236] Killing daemon. [20091112-13:39:56.200397692] Processing File : oprofile.001 [20091112-13:39:56.202727441] Processing File : oprofile-brief.001 [20091112-13:39:57.553942311] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-11-12_1321/btrfs11-12' [20091112-13:40:00.607110453] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20091112-13:40:02.883006863] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20091112-13:40:03.039094388] PROCESSING COMMAND : 'run sequential_reads__threads_0032 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb num_threads=32' [20091112-13:40:03.087255417] new log requested [20091112-13:40:03.123370823] Running command ffsb [20091112-13:40:14.253010443] 11/12/2009-13:40:14 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb Succeeded [20091112-13:40:14.264390217] Importing argument : num_threads=32 [20091112-13:40:14.293170669] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20091112-13:40:14.375003928] FFSB version 6.0-RC2.1 started [20091112-13:40:14.377407328] [20091112-13:40:14.512107153] benchmark time = 300 [20091112-13:40:14.514009158] ThreadGroup 0 [20091112-13:40:14.516015894] ================ [20091112-13:40:14.518216314] num_threads = 32 [20091112-13:40:14.520627009] [20091112-13:40:14.522889809] read_random = off [20091112-13:40:14.525243778] read_size = 0 (0B) [20091112-13:40:14.527462624] read_blocksize = 4096 (4KB) [20091112-13:40:14.529613568] read_skip = off [20091112-13:40:14.531677412] read_skipsize = 0 (0B) [20091112-13:40:14.533666302] [20091112-13:40:14.535720901] write_random = off [20091112-13:40:14.537674639] write_size = 0 (0B) [20091112-13:40:14.539655045] fsync_file = 0 [20091112-13:40:14.541614036] write_blocksize = 0 (0B) [20091112-13:40:14.543705435] wait time = 0 [20091112-13:40:14.545611436] [20091112-13:40:14.547572692] op weights [20091112-13:40:14.549560842] read = 0 (0.00%) [20091112-13:40:14.551459703] readall = 1 (100.00%) [20091112-13:40:14.553454095] write = 0 (0.00%) [20091112-13:40:14.555370597] create = 0 (0.00%) [20091112-13:40:14.557380477] append = 0 (0.00%) [20091112-13:40:14.559438867] delete = 0 (0.00%) [20091112-13:40:14.561431264] metaop = 0 (0.00%) [20091112-13:40:14.563456496] createdir = 0 (0.00%) [20091112-13:40:14.565325658] stat = 0 (0.00%) [20091112-13:40:14.567417706] writeall = 0 (0.00%) [20091112-13:40:14.569340711] writeall_fsync = 0 (0.00%) [20091112-13:40:14.571402952] open_close = 0 (0.00%) [20091112-13:40:14.573496050] write_fsync = 0 (0.00%) [20091112-13:40:14.575475740] create_fsync = 0 (0.00%) [20091112-13:40:14.577489166] append_fsync = 0 (0.00%) [20091112-13:40:14.579355727] [20091112-13:40:14.581351312] FileSystem /mnt/ffsb1 [20091112-13:40:14.583286037] ========== [20091112-13:40:14.585348329] num_dirs = 0 [20091112-13:40:14.587390052] starting files = 1024 [20091112-13:40:14.589380324] [20091112-13:40:14.591386982] min file size = 36700160 (35MB) [20091112-13:40:14.593304456] max file size = 36700160 (35MB) [20091112-13:40:14.595280864] directio = off [20091112-13:40:14.597200797] alignedio = on [20091112-13:40:14.599235528] bufferedio = off [20091112-13:40:14.601270430] [20091112-13:40:14.603174217] aging is off [20091112-13:40:14.605183351] current utilization = 51.27% [20091112-13:40:14.607162711] [20091112-13:40:14.609158471] checking existing fs: /mnt/ffsb1 [20091112-13:40:14.817806031] fs setup took 0 secs [20091112-13:40:15.731760880] Syncing()...0 sec [20091112-13:40:15.733969766] Starting Actual Benchmark At: Thu Nov 12 13:40:15 2009 [20091112-13:40:15.749968138] [20091112-13:45:27.645813370] Syncing()...2 sec [20091112-13:45:27.695628705] FFSB benchmark finished at: Thu Nov 12 13:45:27 2009 [20091112-13:45:27.698622594] [20091112-13:45:27.702091310] Results: [20091112-13:45:27.776413912] Benchmark took 311.53 sec [20091112-13:45:27.779669766] [20091112-13:45:27.783030807] Total Results [20091112-13:45:27.799194914] =============== [20091112-13:45:27.802219163] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20091112-13:45:27.805368832] ======= ============ ========= ======= =========== ========== [20091112-13:45:27.808292307] readall : 7660800 24591.03 100.000% 100.000% 96.1MB/sec [20091112-13:45:27.810802712] - [20091112-13:45:27.813871999] 24591.03 Transactions per Second [20091112-13:45:27.816571830] [20091112-13:45:27.819287269] Throughput Results [20091112-13:45:27.839169943] =================== [20091112-13:45:27.841639208] Read Throughput: 96.1MB/sec [20091112-13:45:27.844054391] [20091112-13:45:27.847188824] System Call Latency statistics in millisecs [20091112-13:45:27.849711269] ===== [20091112-13:45:27.854710747] Min Avg Max Total Calls [20091112-13:45:27.857385319] ======== ======== ======== ============ [20091112-13:45:27.859940759] [ open] 0.006000 40.738815 1964.055054 855 [20091112-13:45:27.862793207] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091112-13:45:27.865498667] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091112-13:45:27.868051181] msec_range[2] 1000.000000 - 2000.000000 : 15 [20091112-13:45:27.870256652] msec_range[3] 500.000000 - 1000.000000 : 17 [20091112-13:45:27.873042236] msec_range[4] 200.000000 - 500.000000 : 6 [20091112-13:45:27.875952076] msec_range[5] 100.000000 - 200.000000 : 1 [20091112-13:45:27.878399707] msec_range[6] 50.000000 - 100.000000 : 0 [20091112-13:45:27.880821100] msec_range[7] 20.000000 - 50.000000 : 0 [20091112-13:45:27.883778842] msec_range[8] 10.000000 - 20.000000 : 0 [20091112-13:45:27.886342483] msec_range[9] 5.000000 - 10.000000 : 0 [20091112-13:45:27.888677476] msec_range[10] 2.000000 - 5.000000 : 0 [20091112-13:45:27.891607379] msec_range[11] 1.000000 - 2.000000 : 0 [20091112-13:45:27.895148585] msec_range[12] 0.500000 - 1.000000 : 0 [20091112-13:45:27.898057205] msec_range[13] 0.200000 - 0.500000 : 2 [20091112-13:45:27.900745378] msec_range[14] 0.100000 - 0.200000 : 124 [20091112-13:45:27.903563334] msec_range[15] 0.050000 - 0.100000 : 336 [20091112-13:45:27.906799556] msec_range[16] 0.020000 - 0.050000 : 296 [20091112-13:45:27.910101404] msec_range[17] 0.010000 - 0.020000 : 28 [20091112-13:45:27.913111107] msec_range[18] 0.000000 - 0.010000 : 30 [20091112-13:45:27.915402474] [20091112-13:45:27.918080912] [ read] 0.001000 1.270109 65538.289062 7660800 [20091112-13:45:27.920761790] msec_range[0] 5000.000000 - 10000.000000 : 1 [20091112-13:45:27.923037819] msec_range[1] 2000.000000 - 5000.000000 : 409 [20091112-13:45:27.925313190] msec_range[2] 1000.000000 - 2000.000000 : 4305 [20091112-13:45:27.927997960] msec_range[3] 500.000000 - 1000.000000 : 3224 [20091112-13:45:27.930918280] msec_range[4] 200.000000 - 500.000000 : 351 [20091112-13:45:27.934411767] msec_range[5] 100.000000 - 200.000000 : 112 [20091112-13:45:27.937168763] msec_range[6] 50.000000 - 100.000000 : 91 [20091112-13:45:27.940146160] msec_range[7] 20.000000 - 50.000000 : 111 [20091112-13:45:27.943517967] msec_range[8] 10.000000 - 20.000000 : 161 [20091112-13:45:27.946254773] msec_range[9] 5.000000 - 10.000000 : 4459 [20091112-13:45:27.949718970] msec_range[10] 2.000000 - 5.000000 : 41503 [20091112-13:45:27.952770084] msec_range[11] 1.000000 - 2.000000 : 599 [20091112-13:45:27.955365620] msec_range[12] 0.500000 - 1.000000 : 707 [20091112-13:45:27.957751595] msec_range[13] 0.200000 - 0.500000 : 258 [20091112-13:45:27.960660379] msec_range[14] 0.100000 - 0.200000 : 66 [20091112-13:45:27.963814750] msec_range[15] 0.050000 - 0.100000 : 83 [20091112-13:45:27.966519364] msec_range[16] 0.020000 - 0.050000 : 15427 [20091112-13:45:27.969779781] msec_range[17] 0.010000 - 0.020000 : 907006 [20091112-13:45:27.972631345] msec_range[18] 0.000000 - 0.010000 : 6681924 [20091112-13:45:27.975526381] [20091112-13:45:27.978113539] [ close] 0.003000 0.008481 0.020000 855 [20091112-13:45:27.980575761] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091112-13:45:27.983419990] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091112-13:45:27.985892581] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091112-13:45:27.988373932] msec_range[3] 500.000000 - 1000.000000 : 0 [20091112-13:45:27.991475277] msec_range[4] 200.000000 - 500.000000 : 0 [20091112-13:45:27.994294094] msec_range[5] 100.000000 - 200.000000 : 0 [20091112-13:45:27.996697343] msec_range[6] 50.000000 - 100.000000 : 0 [20091112-13:45:27.999162353] msec_range[7] 20.000000 - 50.000000 : 0 [20091112-13:45:28.001905384] msec_range[8] 10.000000 - 20.000000 : 0 [20091112-13:45:28.004347871] msec_range[9] 5.000000 - 10.000000 : 0 [20091112-13:45:28.006631599] msec_range[10] 2.000000 - 5.000000 : 0 [20091112-13:45:28.009414747] msec_range[11] 1.000000 - 2.000000 : 0 [20091112-13:45:28.012937017] msec_range[12] 0.500000 - 1.000000 : 0 [20091112-13:45:28.016149345] msec_range[13] 0.200000 - 0.500000 : 0 [20091112-13:45:28.019260545] msec_range[14] 0.100000 - 0.200000 : 0 [20091112-13:45:28.022324653] msec_range[15] 0.050000 - 0.100000 : 0 [20091112-13:45:28.025254436] msec_range[16] 0.020000 - 0.050000 : 1 [20091112-13:45:28.027619324] msec_range[17] 0.010000 - 0.020000 : 176 [20091112-13:45:28.030673555] msec_range[18] 0.000000 - 0.010000 : 678 [20091112-13:45:28.033428517] [20091112-13:45:28.035904999] [20091112-13:45:28.038696618] [20091112-13:45:28.041616457] [20091112-13:45:28.044182865] 1.5% User Time [20091112-13:45:28.046569619] 24.1% System Time [20091112-13:45:28.049104177] 25.5% CPU Utilization [20091112-13:45:28.051776197] Profilers reporting [20091112-13:45:58.667737779] Profilers postprocessing [20091112-13:45:58.949732273] Processing File : iostat.001 [20091112-13:45:58.952098761] Discovered iostat_interval=[5] [20091112-13:46:00.392431318] Processing Directory : sar.breakout.001 [20091112-13:46:00.394863003] Discovered sar_interval=[5] [20091112-13:46:00.584641275] Processing File : mpstat.001 [20091112-13:46:00.589534213] Discovered mpstat_interval=[5] [20091112-13:46:01.734172964] Stopping profiling. [20091112-13:46:01.739423455] Killing daemon. [20091112-13:46:04.071432003] Processing File : oprofile.001 [20091112-13:46:04.073750206] Processing File : oprofile-brief.001 [20091112-13:46:05.544803675] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-11-12_1321/btrfs11-12' [20091112-13:46:08.648625783] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20091112-13:46:11.036165769] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20091112-13:46:11.249861630] PROCESSING COMMAND : 'run random_reads__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb num_threads=1' [20091112-13:46:11.298195375] new log requested [20091112-13:46:11.336769916] Running command ffsb [20091112-13:46:22.496726993] 11/12/2009-13:46:22 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb Succeeded [20091112-13:46:22.508376221] Importing argument : num_threads=1 [20091112-13:46:22.537556889] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20091112-13:46:22.619746079] FFSB version 6.0-RC2.1 started [20091112-13:46:22.622084096] [20091112-13:46:22.624383854] benchmark time = 300 [20091112-13:46:22.626666319] ThreadGroup 0 [20091112-13:46:22.629009289] ================ [20091112-13:46:22.631347481] num_threads = 1 [20091112-13:46:22.633617656] [20091112-13:46:22.635620187] read_random = on [20091112-13:46:22.637601583] read_size = 1048576 (1MB) [20091112-13:46:22.639574310] read_blocksize = 4096 (4KB) [20091112-13:46:22.641591019] read_skip = off [20091112-13:46:22.643572381] read_skipsize = 0 (0B) [20091112-13:46:22.645545612] [20091112-13:46:22.647501172] write_random = off [20091112-13:46:22.649512888] write_size = 0 (0B) [20091112-13:46:22.651420389] fsync_file = 0 [20091112-13:46:22.653395967] write_blocksize = 0 (0B) [20091112-13:46:22.655334068] wait time = 0 [20091112-13:46:22.657288234] [20091112-13:46:22.659145609] op weights [20091112-13:46:22.661068461] read = 1 (100.00%) [20091112-13:46:22.662982061] readall = 0 (0.00%) [20091112-13:46:22.665004862] write = 0 (0.00%) [20091112-13:46:22.666964587] create = 0 (0.00%) [20091112-13:46:22.668968967] append = 0 (0.00%) [20091112-13:46:22.670949420] delete = 0 (0.00%) [20091112-13:46:22.672982894] metaop = 0 (0.00%) [20091112-13:46:22.675169231] createdir = 0 (0.00%) [20091112-13:46:22.677199504] stat = 0 (0.00%) [20091112-13:46:22.679137218] writeall = 0 (0.00%) [20091112-13:46:22.681105653] writeall_fsync = 0 (0.00%) [20091112-13:46:22.683103898] open_close = 0 (0.00%) [20091112-13:46:22.685128814] write_fsync = 0 (0.00%) [20091112-13:46:22.687162631] create_fsync = 0 (0.00%) [20091112-13:46:22.689023862] append_fsync = 0 (0.00%) [20091112-13:46:22.691065419] [20091112-13:46:22.692977334] FileSystem /mnt/ffsb1 [20091112-13:46:22.694976432] ========== [20091112-13:46:22.696955828] num_dirs = 0 [20091112-13:46:22.698946258] starting files = 1024 [20091112-13:46:22.700944640] [20091112-13:46:22.702936305] min file size = 36700160 (35MB) [20091112-13:46:22.704926150] max file size = 36700160 (35MB) [20091112-13:46:22.706910151] directio = off [20091112-13:46:22.708902194] alignedio = on [20091112-13:46:22.710859548] bufferedio = off [20091112-13:46:22.712821038] [20091112-13:46:22.714774392] aging is off [20091112-13:46:22.716749692] current utilization = 51.27% [20091112-13:46:22.718704130] [20091112-13:46:22.720654680] checking existing fs: /mnt/ffsb1 [20091112-13:46:22.920322757] fs setup took 0 secs [20091112-13:46:23.927679243] Syncing()...1 sec [20091112-13:46:23.929907423] Starting Actual Benchmark At: Thu Nov 12 13:46:23 2009 [20091112-13:46:23.944913648] [20091112-13:51:25.484934167] Syncing()...0 sec [20091112-13:51:25.487944116] FFSB benchmark finished at: Thu Nov 12 13:51:25 2009 [20091112-13:51:25.491516278] [20091112-13:51:25.494567532] Results: [20091112-13:51:25.514038551] Benchmark took 301.55 sec [20091112-13:51:25.517321160] [20091112-13:51:25.520517093] Total Results [20091112-13:51:25.540404273] =============== [20091112-13:51:25.543982204] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20091112-13:51:25.547145488] ======= ============ ========= ======= =========== ========== [20091112-13:51:25.549898422] read : 97536 323.44 100.000% 100.000% 1.26MB/sec [20091112-13:51:25.552438020] - [20091112-13:51:25.554971547] 323.44 Transactions per Second [20091112-13:51:25.557706163] [20091112-13:51:25.560852267] Throughput Results [20091112-13:51:25.580021688] =================== [20091112-13:51:25.582935495] Read Throughput: 1.26MB/sec [20091112-13:51:25.586081619] [20091112-13:51:25.588820620] System Call Latency statistics in millisecs [20091112-13:51:25.597134847] ===== [20091112-13:51:25.600237924] Min Avg Max Total Calls [20091112-13:51:25.603061409] ======== ======== ======== ============ [20091112-13:51:25.605703901] [ open] 0.011000 0.021541 0.037000 381 [20091112-13:51:25.608124508] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091112-13:51:25.610889197] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091112-13:51:25.614232556] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091112-13:51:25.617471497] msec_range[3] 500.000000 - 1000.000000 : 0 [20091112-13:51:25.621231809] msec_range[4] 200.000000 - 500.000000 : 0 [20091112-13:51:25.628606250] msec_range[5] 100.000000 - 200.000000 : 0 [20091112-13:51:25.631752926] msec_range[6] 50.000000 - 100.000000 : 0 [20091112-13:51:25.634735176] msec_range[7] 20.000000 - 50.000000 : 0 [20091112-13:51:25.637550047] msec_range[8] 10.000000 - 20.000000 : 0 [20091112-13:51:25.641247306] msec_range[9] 5.000000 - 10.000000 : 0 [20091112-13:51:25.644326438] msec_range[10] 2.000000 - 5.000000 : 0 [20091112-13:51:25.680140567] msec_range[11] 1.000000 - 2.000000 : 0 [20091112-13:51:25.699415692] msec_range[12] 0.500000 - 1.000000 : 0 [20091112-13:51:25.703246818] msec_range[13] 0.200000 - 0.500000 : 0 [20091112-13:51:25.708120928] msec_range[14] 0.100000 - 0.200000 : 0 [20091112-13:51:25.711904965] msec_range[15] 0.050000 - 0.100000 : 0 [20091112-13:51:25.716224696] msec_range[16] 0.020000 - 0.050000 : 211 [20091112-13:51:25.719380076] msec_range[17] 0.010000 - 0.020000 : 170 [20091112-13:51:25.721784417] msec_range[18] 0.000000 - 0.010000 : 0 [20091112-13:51:25.724757911] [20091112-13:51:25.727492896] [ read] 0.002000 3.080506 501.515015 97536 [20091112-13:51:25.730204072] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091112-13:51:25.734015826] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091112-13:51:25.737376512] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091112-13:51:25.741250401] msec_range[3] 500.000000 - 1000.000000 : 1 [20091112-13:51:25.745057667] msec_range[4] 200.000000 - 500.000000 : 0 [20091112-13:51:25.748756344] msec_range[5] 100.000000 - 200.000000 : 0 [20091112-13:51:25.752106482] msec_range[6] 50.000000 - 100.000000 : 3 [20091112-13:51:25.758953470] msec_range[7] 20.000000 - 50.000000 : 222 [20091112-13:51:25.763301478] msec_range[8] 10.000000 - 20.000000 : 2909 [20091112-13:51:25.767920077] msec_range[9] 5.000000 - 10.000000 : 2104 [20091112-13:51:25.773962219] msec_range[10] 2.000000 - 5.000000 : 59368 [20091112-13:51:25.776923748] msec_range[11] 1.000000 - 2.000000 : 18855 [20091112-13:51:25.779760263] msec_range[12] 0.500000 - 1.000000 : 584 [20091112-13:51:25.785186248] msec_range[13] 0.200000 - 0.500000 : 10465 [20091112-13:51:25.787896116] msec_range[14] 0.100000 - 0.200000 : 0 [20091112-13:51:25.791028358] msec_range[15] 0.050000 - 0.100000 : 0 [20091112-13:51:25.793910395] msec_range[16] 0.020000 - 0.050000 : 5 [20091112-13:51:25.796938774] msec_range[17] 0.010000 - 0.020000 : 440 [20091112-13:51:25.800322005] msec_range[18] 0.000000 - 0.010000 : 2580 [20091112-13:51:25.803495918] [20091112-13:51:25.806454759] [ lseek] 0.000000 0.001229 0.022000 97536 [20091112-13:51:25.809704887] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091112-13:51:25.813237907] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091112-13:51:25.821486489] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091112-13:51:25.825421460] msec_range[3] 500.000000 - 1000.000000 : 0 [20091112-13:51:25.830555035] msec_range[4] 200.000000 - 500.000000 : 0 [20091112-13:51:25.833302214] msec_range[5] 100.000000 - 200.000000 : 0 [20091112-13:51:25.836950658] msec_range[6] 50.000000 - 100.000000 : 0 [20091112-13:51:25.840295164] msec_range[7] 20.000000 - 50.000000 : 0 [20091112-13:51:25.845049400] msec_range[8] 10.000000 - 20.000000 : 0 [20091112-13:51:25.847875886] msec_range[9] 5.000000 - 10.000000 : 0 [20091112-13:51:25.852023075] msec_range[10] 2.000000 - 5.000000 : 0 [20091112-13:51:25.855342326] msec_range[11] 1.000000 - 2.000000 : 0 [20091112-13:51:25.859333525] msec_range[12] 0.500000 - 1.000000 : 0 [20091112-13:51:25.862949133] msec_range[13] 0.200000 - 0.500000 : 0 [20091112-13:51:25.868735160] msec_range[14] 0.100000 - 0.200000 : 0 [20091112-13:51:25.872170316] msec_range[15] 0.050000 - 0.100000 : 0 [20091112-13:51:25.875742640] msec_range[16] 0.020000 - 0.050000 : 2 [20091112-13:51:25.878759287] msec_range[17] 0.010000 - 0.020000 : 70 [20091112-13:51:25.883430088] msec_range[18] 0.000000 - 0.010000 : 97464 [20091112-13:51:25.886454620] [20091112-13:51:25.889396693] [ close] 0.002000 0.005976 0.018000 381 [20091112-13:51:25.892470836] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091112-13:51:25.895434196] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091112-13:51:25.898167676] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091112-13:51:25.901056039] msec_range[3] 500.000000 - 1000.000000 : 0 [20091112-13:51:25.903826003] msec_range[4] 200.000000 - 500.000000 : 0 [20091112-13:51:25.906874346] msec_range[5] 100.000000 - 200.000000 : 0 [20091112-13:51:25.911566030] msec_range[6] 50.000000 - 100.000000 : 0 [20091112-13:51:25.914654613] msec_range[7] 20.000000 - 50.000000 : 0 [20091112-13:51:25.917561047] msec_range[8] 10.000000 - 20.000000 : 0 [20091112-13:51:25.920843920] msec_range[9] 5.000000 - 10.000000 : 0 [20091112-13:51:25.923926096] msec_range[10] 2.000000 - 5.000000 : 0 [20091112-13:51:25.926427225] msec_range[11] 1.000000 - 2.000000 : 0 [20091112-13:51:25.929081483] msec_range[12] 0.500000 - 1.000000 : 0 [20091112-13:51:25.931593005] msec_range[13] 0.200000 - 0.500000 : 0 [20091112-13:51:25.934384597] msec_range[14] 0.100000 - 0.200000 : 0 [20091112-13:51:25.937635696] msec_range[15] 0.050000 - 0.100000 : 0 [20091112-13:51:25.940983648] msec_range[16] 0.020000 - 0.050000 : 0 [20091112-13:51:25.943452062] msec_range[17] 0.010000 - 0.020000 : 55 [20091112-13:51:25.945963176] msec_range[18] 0.000000 - 0.010000 : 326 [20091112-13:51:25.948924087] [20091112-13:51:25.951896596] [20091112-13:51:25.954856868] [20091112-13:51:25.957921809] [20091112-13:51:25.960728188] 0.1% User Time [20091112-13:51:25.963343096] 2.0% System Time [20091112-13:51:25.965846034] 2.1% CPU Utilization [20091112-13:51:25.968407423] Profilers reporting [20091112-13:51:45.451046240] Profilers postprocessing [20091112-13:51:45.548455865] Processing File : iostat.001 [20091112-13:51:45.550789075] Discovered iostat_interval=[5] [20091112-13:51:46.237451978] Processing Directory : sar.breakout.001 [20091112-13:51:46.239796528] Discovered sar_interval=[5] [20091112-13:51:46.408256007] Processing File : mpstat.001 [20091112-13:51:46.410471479] Discovered mpstat_interval=[5] [20091112-13:51:47.555247106] Stopping profiling. [20091112-13:51:47.561499453] Killing daemon. [20091112-13:51:48.761015495] Processing File : oprofile.001 [20091112-13:51:48.763193391] Processing File : oprofile-brief.001 [20091112-13:51:49.283788627] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-11-12_1321/btrfs11-12' [20091112-13:51:51.106299353] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20091112-13:51:51.830784887] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20091112-13:51:52.017087608] PROCESSING COMMAND : 'run random_reads__threads_0008 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb num_threads=8' [20091112-13:51:52.065793974] new log requested [20091112-13:51:52.096688701] Running command ffsb [20091112-13:52:01.914201411] 11/12/2009-13:52:01 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb Succeeded [20091112-13:52:01.925692839] Importing argument : num_threads=8 [20091112-13:52:01.954900061] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20091112-13:52:02.030369692] FFSB version 6.0-RC2.1 started [20091112-13:52:02.032717014] [20091112-13:52:02.064712282] benchmark time = 300 [20091112-13:52:02.067125391] ThreadGroup 0 [20091112-13:52:02.069472713] ================ [20091112-13:52:02.071622643] num_threads = 8 [20091112-13:52:02.073774909] [20091112-13:52:02.075794273] read_random = on [20091112-13:52:02.077814202] read_size = 1048576 (1MB) [20091112-13:52:02.079734900] read_blocksize = 4096 (4KB) [20091112-13:52:02.081717183] read_skip = off [20091112-13:52:02.083772841] read_skipsize = 0 (0B) [20091112-13:52:02.085764959] [20091112-13:52:02.087675885] write_random = off [20091112-13:52:02.089671494] write_size = 0 (0B) [20091112-13:52:02.091686946] fsync_file = 0 [20091112-13:52:02.093618450] write_blocksize = 0 (0B) [20091112-13:52:02.095532493] wait time = 0 [20091112-13:52:02.097478149] [20091112-13:52:02.099440908] op weights [20091112-13:52:02.101386544] read = 1 (100.00%) [20091112-13:52:02.103359086] readall = 0 (0.00%) [20091112-13:52:02.105297651] write = 0 (0.00%) [20091112-13:52:02.107256034] create = 0 (0.00%) [20091112-13:52:02.109228108] append = 0 (0.00%) [20091112-13:52:02.111109234] delete = 0 (0.00%) [20091112-13:52:02.113039021] metaop = 0 (0.00%) [20091112-13:52:02.115022444] createdir = 0 (0.00%) [20091112-13:52:02.116982507] stat = 0 (0.00%) [20091112-13:52:02.118832953] writeall = 0 (0.00%) [20091112-13:52:02.120784836] writeall_fsync = 0 (0.00%) [20091112-13:52:02.122782844] open_close = 0 (0.00%) [20091112-13:52:02.124758838] write_fsync = 0 (0.00%) [20091112-13:52:02.126689166] create_fsync = 0 (0.00%) [20091112-13:52:02.128649127] append_fsync = 0 (0.00%) [20091112-13:52:02.130836849] [20091112-13:52:02.132833294] FileSystem /mnt/ffsb1 [20091112-13:52:02.134729955] ========== [20091112-13:52:02.136650698] num_dirs = 0 [20091112-13:52:02.138734499] starting files = 1024 [20091112-13:52:02.140714937] [20091112-13:52:02.142651634] min file size = 36700160 (35MB) [20091112-13:52:02.144619361] max file size = 36700160 (35MB) [20091112-13:52:02.146668160] directio = off [20091112-13:52:02.148640589] alignedio = on [20091112-13:52:02.150546401] bufferedio = off [20091112-13:52:02.152525591] [20091112-13:52:02.154546679] aging is off [20091112-13:52:02.156506994] current utilization = 51.27% [20091112-13:52:02.158422449] [20091112-13:52:02.160350191] checking existing fs: /mnt/ffsb1 [20091112-13:52:02.357813481] fs setup took 0 secs [20091112-13:52:02.972002589] Syncing()...0 sec [20091112-13:52:02.974089739] Starting Actual Benchmark At: Thu Nov 12 13:52:02 2009 [20091112-13:52:02.988920691] [20091112-13:57:08.459496077] Syncing()...1 sec [20091112-13:57:08.462555155] FFSB benchmark finished at: Thu Nov 12 13:57:08 2009 [20091112-13:57:08.465818152] [20091112-13:57:08.469419368] Results: [20091112-13:57:08.485631253] Benchmark took 305.48 sec [20091112-13:57:08.488265002] [20091112-13:57:08.491143787] Total Results [20091112-13:57:08.510094004] =============== [20091112-13:57:08.512649415] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20091112-13:57:08.515014681] ======= ============ ========= ======= =========== ========== [20091112-13:57:08.517687560] read : 118016 386.33 100.000% 100.000% 1.51MB/sec [20091112-13:57:08.520661230] - [20091112-13:57:08.522961027] 386.33 Transactions per Second [20091112-13:57:08.526031404] [20091112-13:57:08.529261257] Throughput Results [20091112-13:57:08.545696626] =================== [20091112-13:57:08.548757169] Read Throughput: 1.51MB/sec [20091112-13:57:08.551369225] [20091112-13:57:08.553945889] System Call Latency statistics in millisecs [20091112-13:57:08.558153274] ===== [20091112-13:57:08.566520224] Min Avg Max Total Calls [20091112-13:57:08.570652313] ======== ======== ======== ============ [20091112-13:57:08.575345599] [ open] 0.007000 0.020074 0.040000 461 [20091112-13:57:08.579895969] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091112-13:57:08.583275809] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091112-13:57:08.586923812] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091112-13:57:08.589908013] msec_range[3] 500.000000 - 1000.000000 : 0 [20091112-13:57:08.591937421] msec_range[4] 200.000000 - 500.000000 : 0 [20091112-13:57:08.594838142] msec_range[5] 100.000000 - 200.000000 : 0 [20091112-13:57:08.597750051] msec_range[6] 50.000000 - 100.000000 : 0 [20091112-13:57:08.600522639] msec_range[7] 20.000000 - 50.000000 : 0 [20091112-13:57:08.612103987] msec_range[8] 10.000000 - 20.000000 : 0 [20091112-13:57:08.615766980] msec_range[9] 5.000000 - 10.000000 : 0 [20091112-13:57:08.619403439] msec_range[10] 2.000000 - 5.000000 : 0 [20091112-13:57:08.622444877] msec_range[11] 1.000000 - 2.000000 : 0 [20091112-13:57:08.627154047] msec_range[12] 0.500000 - 1.000000 : 0 [20091112-13:57:08.630235191] msec_range[13] 0.200000 - 0.500000 : 0 [20091112-13:57:08.633039276] msec_range[14] 0.100000 - 0.200000 : 0 [20091112-13:57:08.635687507] msec_range[15] 0.050000 - 0.100000 : 0 [20091112-13:57:08.641179983] msec_range[16] 0.020000 - 0.050000 : 218 [20091112-13:57:08.644396171] msec_range[17] 0.010000 - 0.020000 : 224 [20091112-13:57:08.647882822] msec_range[18] 0.000000 - 0.010000 : 19 [20091112-13:57:08.651402190] [20091112-13:57:08.654118062] [ read] 0.002000 20.525649 4257.647949 118016 [20091112-13:57:08.657040988] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091112-13:57:08.659221356] msec_range[1] 2000.000000 - 5000.000000 : 20 [20091112-13:57:08.661418826] msec_range[2] 1000.000000 - 2000.000000 : 67 [20091112-13:57:08.670490245] msec_range[3] 500.000000 - 1000.000000 : 22 [20091112-13:57:08.675983000] msec_range[4] 200.000000 - 500.000000 : 528 [20091112-13:57:08.680208619] msec_range[5] 100.000000 - 200.000000 : 3035 [20091112-13:57:08.687443342] msec_range[6] 50.000000 - 100.000000 : 8270 [20091112-13:57:08.692730569] msec_range[7] 20.000000 - 50.000000 : 19042 [20091112-13:57:08.698847952] msec_range[8] 10.000000 - 20.000000 : 18409 [20091112-13:57:08.701338309] msec_range[9] 5.000000 - 10.000000 : 18954 [20091112-13:57:08.703911338] msec_range[10] 2.000000 - 5.000000 : 32299 [20091112-13:57:08.706791306] msec_range[11] 1.000000 - 2.000000 : 12145 [20091112-13:57:08.709790610] msec_range[12] 0.500000 - 1.000000 : 518 [20091112-13:57:08.712109346] msec_range[13] 0.200000 - 0.500000 : 559 [20091112-13:57:08.716002468] msec_range[14] 0.100000 - 0.200000 : 3 [20091112-13:57:08.720060003] msec_range[15] 0.050000 - 0.100000 : 1 [20091112-13:57:08.723287486] msec_range[16] 0.020000 - 0.050000 : 13 [20091112-13:57:08.727629658] msec_range[17] 0.010000 - 0.020000 : 434 [20091112-13:57:08.732532188] msec_range[18] 0.000000 - 0.010000 : 3697 [20091112-13:57:08.735912209] [20091112-13:57:08.743512620] [ lseek] 0.000000 0.001260 0.021000 118016 [20091112-13:57:08.746711864] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091112-13:57:08.749575475] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091112-13:57:08.752533649] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091112-13:57:08.756542257] msec_range[3] 500.000000 - 1000.000000 : 0 [20091112-13:57:08.759633308] msec_range[4] 200.000000 - 500.000000 : 0 [20091112-13:57:08.763017942] msec_range[5] 100.000000 - 200.000000 : 0 [20091112-13:57:08.766103444] msec_range[6] 50.000000 - 100.000000 : 0 [20091112-13:57:08.769245763] msec_range[7] 20.000000 - 50.000000 : 0 [20091112-13:57:08.771678534] msec_range[8] 10.000000 - 20.000000 : 0 [20091112-13:57:08.774584007] msec_range[9] 5.000000 - 10.000000 : 0 [20091112-13:57:08.777724622] msec_range[10] 2.000000 - 5.000000 : 0 [20091112-13:57:08.783403957] msec_range[11] 1.000000 - 2.000000 : 0 [20091112-13:57:08.786916874] msec_range[12] 0.500000 - 1.000000 : 0 [20091112-13:57:08.789813855] msec_range[13] 0.200000 - 0.500000 : 0 [20091112-13:57:08.792193816] msec_range[14] 0.100000 - 0.200000 : 0 [20091112-13:57:08.795021432] msec_range[15] 0.050000 - 0.100000 : 0 [20091112-13:57:08.797658249] msec_range[16] 0.020000 - 0.050000 : 3 [20091112-13:57:08.800166422] msec_range[17] 0.010000 - 0.020000 : 66 [20091112-13:57:08.805723543] msec_range[18] 0.000000 - 0.010000 : 117947 [20091112-13:57:08.808474431] [20091112-13:57:08.810626346] [ close] 0.002000 0.005881 0.016000 461 [20091112-13:57:08.812932705] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091112-13:57:08.816658852] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091112-13:57:08.820029171] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091112-13:57:08.823000168] msec_range[3] 500.000000 - 1000.000000 : 0 [20091112-13:57:08.825654826] msec_range[4] 200.000000 - 500.000000 : 0 [20091112-13:57:08.828504754] msec_range[5] 100.000000 - 200.000000 : 0 [20091112-13:57:08.830944410] msec_range[6] 50.000000 - 100.000000 : 0 [20091112-13:57:08.833560478] msec_range[7] 20.000000 - 50.000000 : 0 [20091112-13:57:08.836569175] msec_range[8] 10.000000 - 20.000000 : 0 [20091112-13:57:08.839118955] msec_range[9] 5.000000 - 10.000000 : 0 [20091112-13:57:08.842118406] msec_range[10] 2.000000 - 5.000000 : 0 [20091112-13:57:08.845616053] msec_range[11] 1.000000 - 2.000000 : 0 [20091112-13:57:08.848124291] msec_range[12] 0.500000 - 1.000000 : 0 [20091112-13:57:08.850858501] msec_range[13] 0.200000 - 0.500000 : 0 [20091112-13:57:08.853299666] msec_range[14] 0.100000 - 0.200000 : 0 [20091112-13:57:08.855617225] msec_range[15] 0.050000 - 0.100000 : 0 [20091112-13:57:08.858195301] msec_range[16] 0.020000 - 0.050000 : 0 [20091112-13:57:08.860446454] msec_range[17] 0.010000 - 0.020000 : 42 [20091112-13:57:08.862838512] msec_range[18] 0.000000 - 0.010000 : 419 [20091112-13:57:08.865096218] [20091112-13:57:08.867270864] [20091112-13:57:08.870173553] [20091112-13:57:08.873977854] [20091112-13:57:08.876465161] 0.1% User Time [20091112-13:57:08.878965786] 2.4% System Time [20091112-13:57:08.881368202] 2.4% CPU Utilization [20091112-13:57:08.883669835] Profilers reporting [20091112-13:57:08.885871886] /autobench/scripts/doprofilers: line 2: 10933 Terminated ${CMDS[$i]} [20091112-13:57:08.888274863] /autobench/scripts/doprofilers: line 2: 10947 Terminated ${CMDS[$i]} [20091112-13:57:08.890801614] /autobench/scripts/doprofilers: line 2: 10979 Terminated ${CMDS[$i]} [20091112-13:57:26.033938274] Profilers postprocessing [20091112-13:57:26.131254256] Processing File : iostat.001 [20091112-13:57:26.133766536] Discovered iostat_interval=[5] [20091112-13:57:26.848699266] Processing Directory : sar.breakout.001 [20091112-13:57:26.851097902] Discovered sar_interval=[5] [20091112-13:57:27.022228684] Processing File : mpstat.001 [20091112-13:57:27.024883584] Discovered mpstat_interval=[5] [20091112-13:57:28.170563832] Stopping profiling. [20091112-13:57:28.177533811] Killing daemon. [20091112-13:57:29.392035230] Processing File : oprofile.001 [20091112-13:57:29.394376819] Processing File : oprofile-brief.001 [20091112-13:57:29.890759200] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-11-12_1321/btrfs11-12'