[20090605-10:47:31.773118373] PROCESSING COMMAND : 'clearprofilers' [20090605-10:47:32.048616889] PROCESSING COMMAND : 'useprofiler iostat 5' [20090605-10:47:32.169256252] Checking for sar... [20090605-10:47:32.171590611] found [20090605-10:47:32.322310085] PROCESSING COMMAND : 'useprofiler sar 5' [20090605-10:47:32.443983137] Checking for sar... [20090605-10:47:32.446340383] found [20090605-10:47:32.599032652] PROCESSING COMMAND : 'useprofiler mpstat 5' [20090605-10:47:32.718940525] Checking for sar... [20090605-10:47:32.721297603] found [20090605-10:47:32.908037317] PROCESSING COMMAND : 'useprofiler oprofile' [20090605-10:47:33.064882844] Checking for gettext... [20090605-10:47:33.067353485] found [20090605-10:47:33.069625383] Checking for libiberty in autobench... [20090605-10:47:33.071762740] found [20090605-10:47:33.073812292] Checking for popt... [20090605-10:47:33.075979446] found [20090605-10:47:33.078197120] Checking for popt64... [20090605-10:47:33.080207310] found [20090605-10:47:33.082358450] Checking for oprofile... [20090605-10:47:33.084349089] found [20090605-10:47:33.142639490] opcontrol: oprofile 0.9.5cvs-P7 compiled on Jun 2 2009 12:44:23 [20090605-10:47:33.331077937] dump fail: daemon died during last run ? [20090605-10:47:33.334019445] Detected stale lock file. Removing. [20090605-10:47:33.729439102] OPROFILE : using callgraph [5] [20090605-10:47:33.973848172] Daemon not running [20090605-10:47:33.976099607] Separate options: none [20090605-10:47:33.978318325] vmlinux file: /boot/vmlinux-2.6.30-rc7-autokern1 [20090605-10:47:33.980703218] Image filter: none [20090605-10:47:33.982746422] Call-graph depth: 5 [20090605-10:47:34.207210248] PROCESSING COMMAND : 'umount /mnt/ffsb1 > /dev/null 2>&1' [20090605-10:47:34.285963334] PROCESSING COMMAND : 'set-sched noop' [20090605-10:47:34.614501951] PROCESSING COMMAND : 'mkresultdirs hks.austin.ibm.com benchmarks/results/btrfs/ffsb btrfs1 2009-06-05_1047 btrfsnewformat-6-1-nodatacow' [20090605-10:47:34.914948973] Connecting to hks.austin.ibm.com... [20090605-10:47:34.917304747] Remote working directory: /opt [20090605-10:47:34.921033383] Remote working directory: /opt/benchmarks/results/btrfs/ffsb [20090605-10:47:34.923277229] Couldn't create directory: Failure [20090605-10:47:34.925447188] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1 [20090605-10:47:34.927381569] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs1 [20090605-10:47:34.929589990] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1/2009-06-05_1047 [20090605-10:47:34.931824425] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs1/2009-06-05_1047 [20090605-10:47:34.934152257] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1/2009-06-05_1047/btrfsnewformat-6-1-nodatacow [20090605-10:47:34.992158237] ONLY : Command [mkfs.btrfs 2>&1] found for me [20090605-10:47:35.043899016] PROCESSING COMMAND : 'mkfs.btrfs 2>&1' [20090605-10:47:35.065222091] usage: mkfs.btrfs [options] dev [ dev ... ] [20090605-10:47:35.067690484] options: [20090605-10:47:35.069969007] -A --alloc-start the offset to start the FS [20090605-10:47:35.071996553] -b --byte-count total number of bytes in the FS [20090605-10:47:35.074185298] -d --data data profile, raid0, raid1, raid10 or single [20090605-10:47:35.076122056] -l --leafsize size of btree leaves [20090605-10:47:35.078024944] -L --label set a label [20090605-10:47:35.080279112] -m --metadata metadata profile, values like data profile [20090605-10:47:35.082580575] -n --nodesize size of btree nodes [20090605-10:47:35.084881001] -s --sectorsize min block allocation [20090605-10:47:35.087088774] Btrfs v0.18-13-gb8420fa [20090605-10:47:35.166958121] PROCESSING COMMAND : 'mkfs.btrfs /dev/ffsbdev1' [20090605-10:47:35.205310365] [20090605-10:47:35.207523626] WARNING! - Btrfs v0.18-13-gb8420fa IS EXPERIMENTAL [20090605-10:47:35.209948711] WARNING! - see http://btrfs.wiki.kernel.org before using [20090605-10:47:35.212191726] [20090605-10:47:35.214769802] fs created label (null) on /dev/ffsbdev1 [20090605-10:47:35.217269669] nodesize 4096 leafsize 4096 sectorsize 4096 size 2.18TB [20090605-10:47:35.219367901] Btrfs v0.18-13-gb8420fa [20090605-10:47:35.386315449] PROCESSING COMMAND : 'mount -t btrfs -o nodatacow /dev/ffsbdev1 /mnt/ffsb1' [20090605-10:47:35.520129073] ONLY : Command [run sequential_reads__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb reuse=1 num_threads=1] found for me [20090605-10:47:35.572243057] PROCESSING COMMAND : 'run sequential_reads__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb reuse=1 num_threads=1' [20090605-10:47:35.621226514] new log requested [20090605-10:47:35.651911389] Running command ffsb [20090605-10:47:47.130666699] 06/05/2009-10:47:47 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb Succeeded [20090605-10:47:47.142006110] Importing argument : reuse=1 [20090605-10:47:47.155308127] Importing argument : num_threads=1 [20090605-10:47:47.185823979] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090605-10:47:47.285487235] FFSB version 6.0-RC2.1 started [20090605-10:47:47.287733647] [20090605-10:47:47.289924858] benchmark time = 300 [20090605-10:47:47.292210627] ThreadGroup 0 [20090605-10:47:47.294533129] ================ [20090605-10:47:47.296906093] num_threads = 1 [20090605-10:47:47.299152604] [20090605-10:47:47.301310899] read_random = off [20090605-10:47:47.303401572] read_size = 0 (0B) [20090605-10:47:47.305531503] read_blocksize = 4096 (4KB) [20090605-10:47:47.307526007] read_skip = off [20090605-10:47:47.309600862] read_skipsize = 0 (0B) [20090605-10:47:47.311666656] [20090605-10:47:47.313659569] write_random = off [20090605-10:47:47.315668050] write_size = 0 (0B) [20090605-10:47:47.317686057] fsync_file = 0 [20090605-10:47:47.319703847] write_blocksize = 0 (0B) [20090605-10:47:47.321643078] wait time = 0 [20090605-10:47:47.323704110] [20090605-10:47:47.325739237] op weights [20090605-10:47:47.327763563] read = 0 (0.00%) [20090605-10:47:47.329713637] readall = 1 (100.00%) [20090605-10:47:47.331716237] write = 0 (0.00%) [20090605-10:47:47.333626835] create = 0 (0.00%) [20090605-10:47:47.335681348] append = 0 (0.00%) [20090605-10:47:47.337750596] delete = 0 (0.00%) [20090605-10:47:47.339790788] metaop = 0 (0.00%) [20090605-10:47:47.341750042] createdir = 0 (0.00%) [20090605-10:47:47.343746448] stat = 0 (0.00%) [20090605-10:47:47.345681171] writeall = 0 (0.00%) [20090605-10:47:47.347735729] writeall_fsync = 0 (0.00%) [20090605-10:47:47.349798574] open_close = 0 (0.00%) [20090605-10:47:47.351805988] write_fsync = 0 (0.00%) [20090605-10:47:47.353779833] create_fsync = 0 (0.00%) [20090605-10:47:47.355780019] append_fsync = 0 (0.00%) [20090605-10:47:47.357689269] [20090605-10:47:47.359739528] FileSystem /mnt/ffsb1 [20090605-10:47:47.361793122] ========== [20090605-10:47:47.363808583] num_dirs = 0 [20090605-10:47:47.365763755] starting files = 1024 [20090605-10:47:47.367781439] [20090605-10:47:47.369675254] min file size = 104857600 (100MB) [20090605-10:47:47.371739906] max file size = 104857600 (100MB) [20090605-10:47:47.373796256] directio = off [20090605-10:47:47.375715668] alignedio = on [20090605-10:47:47.377722940] bufferedio = off [20090605-10:47:47.379712733] [20090605-10:47:47.381708903] aging is off [20090605-10:47:47.383628224] current utilization = 0.00% [20090605-10:47:47.385622650] [20090605-10:47:47.387584995] checking existing fs: /mnt/ffsb1 [20090605-10:47:47.389619310] opendir: No such file or directory [20090605-10:47:47.391680777] recreating new fileset [20090605-10:55:29.654167536] fs setup took 462 secs [20090605-10:55:30.117024148] Syncing()...0 sec [20090605-10:55:30.119765488] Starting Actual Benchmark At: Fri Jun 5 10:55:30 2009 [20090605-10:55:30.163368197] [20090605-11:00:31.990456400] Syncing()...0 sec [20090605-11:00:32.061135602] FFSB benchmark finished at: Fri Jun 5 11:00:31 2009 [20090605-11:00:32.064463702] [20090605-11:00:32.068005461] Results: [20090605-11:00:32.115906828] Benchmark took 301.53 sec [20090605-11:00:32.118680802] [20090605-11:00:32.121765749] Total Results [20090605-11:00:32.139891382] =============== [20090605-11:00:32.142740389] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090605-11:00:32.145816733] ======= ============ ========= ======= =========== ========== [20090605-11:00:32.148764222] readall : 29875200 99079.91 100.000% 100.000% 387MB/sec [20090605-11:00:32.151941459] - [20090605-11:00:32.155036037] 99079.91 Transactions per Second [20090605-11:00:32.158296250] [20090605-11:00:32.161150598] Throughput Results [20090605-11:00:32.178751993] =================== [20090605-11:00:32.181292113] Read Throughput: 387MB/sec [20090605-11:00:32.184043937] [20090605-11:00:32.186736968] System Call Latency statistics in millisecs [20090605-11:00:32.189242605] ===== [20090605-11:00:32.192050173] Min Avg Max Total Calls [20090605-11:00:32.194788083] ======== ======== ======== ============ [20090605-11:00:32.197352517] [ open] 0.016000 0.488676 16.229000 1167 [20090605-11:00:32.199885656] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:00:32.202450580] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:00:32.205101491] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:00:32.207624761] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:00:32.210305987] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:00:32.212821392] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-11:00:32.215476061] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-11:00:32.218069892] msec_range[7] 20.000000 - 50.000000 : 0 [20090605-11:00:32.220640557] msec_range[8] 10.000000 - 20.000000 : 7 [20090605-11:00:32.223170377] msec_range[9] 5.000000 - 10.000000 : 47 [20090605-11:00:32.225857196] msec_range[10] 2.000000 - 5.000000 : 37 [20090605-11:00:32.228483730] msec_range[11] 1.000000 - 2.000000 : 2 [20090605-11:00:32.231013473] msec_range[12] 0.500000 - 1.000000 : 6 [20090605-11:00:32.233677391] msec_range[13] 0.200000 - 0.500000 : 0 [20090605-11:00:32.236261284] msec_range[14] 0.100000 - 0.200000 : 3 [20090605-11:00:32.238921115] msec_range[15] 0.050000 - 0.100000 : 435 [20090605-11:00:32.241712981] msec_range[16] 0.020000 - 0.050000 : 625 [20090605-11:00:32.244671661] msec_range[17] 0.010000 - 0.020000 : 5 [20090605-11:00:32.247601656] msec_range[18] 0.000000 - 0.010000 : 0 [20090605-11:00:32.250500612] [20090605-11:00:32.253278335] [ read] 0.004000 0.009823 200.544998 29875200 [20090605-11:00:32.255874996] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:00:32.259476170] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:00:32.262438678] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:00:32.265252012] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:00:32.268017411] msec_range[4] 200.000000 - 500.000000 : 1 [20090605-11:00:32.270723848] msec_range[5] 100.000000 - 200.000000 : 1 [20090605-11:00:32.273322260] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-11:00:32.275987015] msec_range[7] 20.000000 - 50.000000 : 27 [20090605-11:00:32.278456992] msec_range[8] 10.000000 - 20.000000 : 532 [20090605-11:00:32.281021999] msec_range[9] 5.000000 - 10.000000 : 3684 [20090605-11:00:32.283600828] msec_range[10] 2.000000 - 5.000000 : 29051 [20090605-11:00:32.286486661] msec_range[11] 1.000000 - 2.000000 : 3217 [20090605-11:00:32.289248749] msec_range[12] 0.500000 - 1.000000 : 2300 [20090605-11:00:32.292187192] msec_range[13] 0.200000 - 0.500000 : 4519 [20090605-11:00:32.294912991] msec_range[14] 0.100000 - 0.200000 : 19491 [20090605-11:00:32.297601438] msec_range[15] 0.050000 - 0.100000 : 17126 [20090605-11:00:32.301152336] msec_range[16] 0.020000 - 0.050000 : 15397 [20090605-11:00:32.303985313] msec_range[17] 0.010000 - 0.020000 : 66332 [20090605-11:00:32.306572176] msec_range[18] 0.000000 - 0.010000 : 29713522 [20090605-11:00:32.309424493] [20090605-11:00:32.312260660] [ close] 0.006000 0.007560 0.015000 1167 [20090605-11:00:32.315083213] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:00:32.317840543] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:00:32.320512852] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:00:32.322915131] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:00:32.325689707] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:00:32.328296254] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-11:00:32.330958238] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-11:00:32.333898236] msec_range[7] 20.000000 - 50.000000 : 0 [20090605-11:00:32.336805867] msec_range[8] 10.000000 - 20.000000 : 0 [20090605-11:00:32.339869630] msec_range[9] 5.000000 - 10.000000 : 0 [20090605-11:00:32.342576392] msec_range[10] 2.000000 - 5.000000 : 0 [20090605-11:00:32.345308507] msec_range[11] 1.000000 - 2.000000 : 0 [20090605-11:00:32.348006966] msec_range[12] 0.500000 - 1.000000 : 0 [20090605-11:00:32.350771191] msec_range[13] 0.200000 - 0.500000 : 0 [20090605-11:00:32.353546035] msec_range[14] 0.100000 - 0.200000 : 0 [20090605-11:00:32.356271915] msec_range[15] 0.050000 - 0.100000 : 0 [20090605-11:00:32.359106345] msec_range[16] 0.020000 - 0.050000 : 0 [20090605-11:00:32.361951979] msec_range[17] 0.010000 - 0.020000 : 38 [20090605-11:00:32.364717221] msec_range[18] 0.000000 - 0.010000 : 1129 [20090605-11:00:32.367511312] [20090605-11:00:32.370804639] [20090605-11:00:32.373506686] [20090605-11:00:32.376218262] [20090605-11:00:32.378884626] 6.6% User Time [20090605-11:00:32.381690751] 77.2% System Time [20090605-11:00:32.384188063] 83.9% CPU Utilization [20090605-11:00:32.386781812] Profilers reporting [20090605-11:00:46.030139168] Profilers postprocessing [20090605-11:00:46.306735165] Processing File : iostat.001 [20090605-11:00:46.309161984] Discovered iostat_interval=[5] [20090605-11:00:47.090558295] Processing Directory : sar.breakout.001 [20090605-11:00:47.092984239] Discovered sar_interval=[5] [20090605-11:00:47.268826217] Processing File : mpstat.001 [20090605-11:00:47.271094761] Discovered mpstat_interval=[5] [20090605-11:00:48.416463582] Stopping profiling. [20090605-11:00:48.422047866] Killing daemon. [20090605-11:00:49.684829588] Processing File : oprofile.001 [20090605-11:00:49.687009219] Processing File : oprofile-brief.001 [20090605-11:00:51.250217950] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-06-05_1047/btrfsnewformat-6-1-nodatacow' [20090605-11:00:55.176924559] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090605-11:00:57.475566853] PROCESSING COMMAND : 'mount -t btrfs -o nodatacow /dev/ffsbdev1 /mnt/ffsb1' [20090605-11:00:57.730152263] ONLY : Command [run sequential_reads__threads_0016 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb reuse=1 num_threads=16] found for me [20090605-11:00:57.784471891] PROCESSING COMMAND : 'run sequential_reads__threads_0016 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb reuse=1 num_threads=16' [20090605-11:00:57.833201704] new log requested [20090605-11:00:57.865403424] Running command ffsb [20090605-11:01:09.082963112] 06/05/2009-11:01:09 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb Succeeded [20090605-11:01:09.094175052] Importing argument : reuse=1 [20090605-11:01:09.107853617] Importing argument : num_threads=16 [20090605-11:01:09.137336641] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090605-11:01:09.374327131] FFSB version 6.0-RC2.1 started [20090605-11:01:09.376653907] [20090605-11:01:09.440894973] benchmark time = 300 [20090605-11:01:09.443154111] ThreadGroup 0 [20090605-11:01:09.445432875] ================ [20090605-11:01:09.447704891] num_threads = 16 [20090605-11:01:09.449764192] [20090605-11:01:09.451642552] read_random = off [20090605-11:01:09.453581059] read_size = 0 (0B) [20090605-11:01:09.455532530] read_blocksize = 4096 (4KB) [20090605-11:01:09.457500913] read_skip = off [20090605-11:01:09.459376658] read_skipsize = 0 (0B) [20090605-11:01:09.461436785] [20090605-11:01:09.463549611] write_random = off [20090605-11:01:09.465511775] write_size = 0 (0B) [20090605-11:01:09.467545887] fsync_file = 0 [20090605-11:01:09.469653956] write_blocksize = 0 (0B) [20090605-11:01:09.471780744] wait time = 0 [20090605-11:01:09.473688763] [20090605-11:01:09.475731598] op weights [20090605-11:01:09.477750868] read = 0 (0.00%) [20090605-11:01:09.479812840] readall = 1 (100.00%) [20090605-11:01:09.481844016] write = 0 (0.00%) [20090605-11:01:09.483779586] create = 0 (0.00%) [20090605-11:01:09.485804094] append = 0 (0.00%) [20090605-11:01:09.487953206] delete = 0 (0.00%) [20090605-11:01:09.490017539] metaop = 0 (0.00%) [20090605-11:01:09.491909880] createdir = 0 (0.00%) [20090605-11:01:09.493874224] stat = 0 (0.00%) [20090605-11:01:09.495774613] writeall = 0 (0.00%) [20090605-11:01:09.497751275] writeall_fsync = 0 (0.00%) [20090605-11:01:09.499639692] open_close = 0 (0.00%) [20090605-11:01:09.501605727] write_fsync = 0 (0.00%) [20090605-11:01:09.503504994] create_fsync = 0 (0.00%) [20090605-11:01:09.505438605] append_fsync = 0 (0.00%) [20090605-11:01:09.507300584] [20090605-11:01:09.509268490] FileSystem /mnt/ffsb1 [20090605-11:01:09.511158198] ========== [20090605-11:01:09.513149477] num_dirs = 0 [20090605-11:01:09.515181537] starting files = 1024 [20090605-11:01:09.517129961] [20090605-11:01:09.519139450] min file size = 104857600 (100MB) [20090605-11:01:09.521055633] max file size = 104857600 (100MB) [20090605-11:01:09.523005713] directio = off [20090605-11:01:09.524891163] alignedio = on [20090605-11:01:09.526872477] bufferedio = off [20090605-11:01:09.528779163] [20090605-11:01:09.530780283] aging is off [20090605-11:01:09.532651610] current utilization = 4.47% [20090605-11:01:09.534591932] [20090605-11:01:09.536507822] checking existing fs: /mnt/ffsb1 [20090605-11:01:09.663496317] fs setup took 0 secs [20090605-11:01:10.108385460] Syncing()...0 sec [20090605-11:01:10.110622199] Starting Actual Benchmark At: Fri Jun 5 11:01:10 2009 [20090605-11:01:10.126373136] [20090605-11:06:13.344269663] Syncing()...0 sec [20090605-11:06:13.408460207] FFSB benchmark finished at: Fri Jun 5 11:06:12 2009 [20090605-11:06:13.411805737] [20090605-11:06:13.415239996] Results: [20090605-11:06:13.508298918] Benchmark took 302.77 sec [20090605-11:06:13.511476167] [20090605-11:06:13.514459745] Total Results [20090605-11:06:13.531828951] =============== [20090605-11:06:13.534465165] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090605-11:06:13.537507561] ======= ============ ========= ======= =========== ========== [20090605-11:06:13.540710250] readall : 51712000 170798.93 100.000% 100.000% 667MB/sec [20090605-11:06:13.543402907] - [20090605-11:06:13.546447270] 170798.93 Transactions per Second [20090605-11:06:13.549274853] [20090605-11:06:13.552321925] Throughput Results [20090605-11:06:13.570483619] =================== [20090605-11:06:13.573840060] Read Throughput: 667MB/sec [20090605-11:06:13.576951964] [20090605-11:06:13.579939467] System Call Latency statistics in millisecs [20090605-11:06:13.583353533] ===== [20090605-11:06:13.585902773] Min Avg Max Total Calls [20090605-11:06:13.588434190] ======== ======== ======== ============ [20090605-11:06:13.591124810] [ open] 0.006000 3.239956 174.712997 2020 [20090605-11:06:13.593795063] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:06:13.596304957] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:06:13.599174866] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:06:13.602032336] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:06:13.604562323] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:06:13.606966936] msec_range[5] 100.000000 - 200.000000 : 10 [20090605-11:06:13.609801464] msec_range[6] 50.000000 - 100.000000 : 25 [20090605-11:06:13.612469293] msec_range[7] 20.000000 - 50.000000 : 62 [20090605-11:06:13.614837594] msec_range[8] 10.000000 - 20.000000 : 91 [20090605-11:06:13.617147826] msec_range[9] 5.000000 - 10.000000 : 50 [20090605-11:06:13.619885561] msec_range[10] 2.000000 - 5.000000 : 6 [20090605-11:06:13.622453902] msec_range[11] 1.000000 - 2.000000 : 3 [20090605-11:06:13.624770644] msec_range[12] 0.500000 - 1.000000 : 0 [20090605-11:06:13.627071695] msec_range[13] 0.200000 - 0.500000 : 3 [20090605-11:06:13.629728021] msec_range[14] 0.100000 - 0.200000 : 93 [20090605-11:06:13.632367091] msec_range[15] 0.050000 - 0.100000 : 744 [20090605-11:06:13.635494599] msec_range[16] 0.020000 - 0.050000 : 909 [20090605-11:06:13.639228722] msec_range[17] 0.010000 - 0.020000 : 13 [20090605-11:06:13.642115606] msec_range[18] 0.000000 - 0.010000 : 11 [20090605-11:06:13.644851077] [20090605-11:06:13.647785832] [ read] 0.002000 0.092941 287.040985 51712000 [20090605-11:06:13.650571949] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:06:13.653196526] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:06:13.655534381] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:06:13.658257911] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:06:13.660820092] msec_range[4] 200.000000 - 500.000000 : 45 [20090605-11:06:13.663144691] msec_range[5] 100.000000 - 200.000000 : 9458 [20090605-11:06:13.665640466] msec_range[6] 50.000000 - 100.000000 : 23647 [20090605-11:06:13.668563265] msec_range[7] 20.000000 - 50.000000 : 32531 [20090605-11:06:13.671486676] msec_range[8] 10.000000 - 20.000000 : 19377 [20090605-11:06:13.674251580] msec_range[9] 5.000000 - 10.000000 : 18218 [20090605-11:06:13.677114406] msec_range[10] 2.000000 - 5.000000 : 30307 [20090605-11:06:13.679974010] msec_range[11] 1.000000 - 2.000000 : 2984 [20090605-11:06:13.682690717] msec_range[12] 0.500000 - 1.000000 : 2852 [20090605-11:06:13.686961779] msec_range[13] 0.200000 - 0.500000 : 6838 [20090605-11:06:13.689517080] msec_range[14] 0.100000 - 0.200000 : 11034 [20090605-11:06:13.692284408] msec_range[15] 0.050000 - 0.100000 : 34043 [20090605-11:06:13.695034608] msec_range[16] 0.020000 - 0.050000 : 102289 [20090605-11:06:13.697821029] msec_range[17] 0.010000 - 0.020000 : 2354885 [20090605-11:06:13.700452118] msec_range[18] 0.000000 - 0.010000 : 49063492 [20090605-11:06:13.703044212] [20090605-11:06:13.706057866] [ close] 0.003000 0.008797 0.193000 2020 [20090605-11:06:13.708952448] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:06:13.711619034] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:06:13.714100809] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:06:13.717017735] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:06:13.719657114] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:06:13.722391406] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-11:06:13.725173197] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-11:06:13.727724655] msec_range[7] 20.000000 - 50.000000 : 0 [20090605-11:06:13.730385061] msec_range[8] 10.000000 - 20.000000 : 0 [20090605-11:06:13.733288315] msec_range[9] 5.000000 - 10.000000 : 0 [20090605-11:06:13.736090947] msec_range[10] 2.000000 - 5.000000 : 0 [20090605-11:06:13.738796596] msec_range[11] 1.000000 - 2.000000 : 0 [20090605-11:06:13.741608244] msec_range[12] 0.500000 - 1.000000 : 0 [20090605-11:06:13.744341274] msec_range[13] 0.200000 - 0.500000 : 0 [20090605-11:06:13.747934271] msec_range[14] 0.100000 - 0.200000 : 1 [20090605-11:06:13.750738324] msec_range[15] 0.050000 - 0.100000 : 1 [20090605-11:06:13.753493972] msec_range[16] 0.020000 - 0.050000 : 6 [20090605-11:06:13.756319513] msec_range[17] 0.010000 - 0.020000 : 503 [20090605-11:06:13.758963424] msec_range[18] 0.000000 - 0.010000 : 1509 [20090605-11:06:13.761812589] [20090605-11:06:13.764484408] [20090605-11:06:13.767321472] [20090605-11:06:13.769886775] [20090605-11:06:13.772409024] 11.0% User Time [20090605-11:06:13.775224464] 175.9% System Time [20090605-11:06:13.777901354] 186.9% CPU Utilization [20090605-11:06:13.780494475] Profilers reporting [20090605-11:06:30.096183341] Profilers postprocessing [20090605-11:06:30.355874820] Processing File : iostat.001 [20090605-11:06:30.358345556] Discovered iostat_interval=[5] [20090605-11:06:31.131617734] Processing Directory : sar.breakout.001 [20090605-11:06:31.133809512] Discovered sar_interval=[5] [20090605-11:06:31.311266540] Processing File : mpstat.001 [20090605-11:06:31.313492722] Discovered mpstat_interval=[5] [20090605-11:06:32.460129511] Stopping profiling. [20090605-11:06:32.465517468] Killing daemon. [20090605-11:06:34.734867175] Processing File : oprofile.001 [20090605-11:06:34.737081424] Processing File : oprofile-brief.001 [20090605-11:06:36.302106955] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-06-05_1047/btrfsnewformat-6-1-nodatacow' [20090605-11:06:40.145019618] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090605-11:06:42.605583564] PROCESSING COMMAND : 'mount -t btrfs -o nodatacow /dev/ffsbdev1 /mnt/ffsb1' [20090605-11:06:42.842878177] ONLY : Command [run sequential_reads__threads_0128 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb reuse=1 num_threads=128] found for me [20090605-11:06:42.896185333] PROCESSING COMMAND : 'run sequential_reads__threads_0128 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb reuse=1 num_threads=128' [20090605-11:06:42.945729222] new log requested [20090605-11:06:42.986551619] Running command ffsb [20090605-11:06:54.283455619] 06/05/2009-11:06:54 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb Succeeded [20090605-11:06:54.294686767] Importing argument : reuse=1 [20090605-11:06:54.307670885] Importing argument : num_threads=128 [20090605-11:06:54.336827337] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090605-11:06:54.419946765] FFSB version 6.0-RC2.1 started [20090605-11:06:54.422359362] [20090605-11:06:54.952132478] benchmark time = 300 [20090605-11:06:54.954390456] ThreadGroup 0 [20090605-11:06:54.956678158] ================ [20090605-11:06:54.958820890] num_threads = 128 [20090605-11:06:54.961166382] [20090605-11:06:54.963191612] read_random = off [20090605-11:06:54.965530309] read_size = 0 (0B) [20090605-11:06:54.967598056] read_blocksize = 4096 (4KB) [20090605-11:06:54.969528913] read_skip = off [20090605-11:06:54.971556224] read_skipsize = 0 (0B) [20090605-11:06:54.973716962] [20090605-11:06:54.975812044] write_random = off [20090605-11:06:54.977749694] write_size = 0 (0B) [20090605-11:06:54.979725401] fsync_file = 0 [20090605-11:06:54.981688170] write_blocksize = 0 (0B) [20090605-11:06:54.983590730] wait time = 0 [20090605-11:06:54.985570543] [20090605-11:06:54.987537236] op weights [20090605-11:06:54.989450380] read = 0 (0.00%) [20090605-11:06:54.991422014] readall = 1 (100.00%) [20090605-11:06:54.993413239] write = 0 (0.00%) [20090605-11:06:54.995501268] create = 0 (0.00%) [20090605-11:06:54.997638200] append = 0 (0.00%) [20090605-11:06:54.999622876] delete = 0 (0.00%) [20090605-11:06:55.001637533] metaop = 0 (0.00%) [20090605-11:06:55.003590755] createdir = 0 (0.00%) [20090605-11:06:55.005609051] stat = 0 (0.00%) [20090605-11:06:55.007565921] writeall = 0 (0.00%) [20090605-11:06:55.009458484] writeall_fsync = 0 (0.00%) [20090605-11:06:55.011453597] open_close = 0 (0.00%) [20090605-11:06:55.013384703] write_fsync = 0 (0.00%) [20090605-11:06:55.015352543] create_fsync = 0 (0.00%) [20090605-11:06:55.017256003] append_fsync = 0 (0.00%) [20090605-11:06:55.019194926] [20090605-11:06:55.021151436] FileSystem /mnt/ffsb1 [20090605-11:06:55.023070959] ========== [20090605-11:06:55.025056768] num_dirs = 0 [20090605-11:06:55.027024959] starting files = 1024 [20090605-11:06:55.028897585] [20090605-11:06:55.030903463] min file size = 104857600 (100MB) [20090605-11:06:55.032822285] max file size = 104857600 (100MB) [20090605-11:06:55.034809691] directio = off [20090605-11:06:55.036700131] alignedio = on [20090605-11:06:55.038635430] bufferedio = off [20090605-11:06:55.040555679] [20090605-11:06:55.042561140] aging is off [20090605-11:06:55.044452863] current utilization = 4.47% [20090605-11:06:55.046398165] [20090605-11:06:55.048333470] checking existing fs: /mnt/ffsb1 [20090605-11:06:55.188318232] fs setup took 0 secs [20090605-11:06:55.600716818] Syncing()...0 sec [20090605-11:06:55.607368377] Starting Actual Benchmark At: Fri Jun 5 11:06:55 2009 [20090605-11:06:55.632476656] [20090605-11:12:06.127761887] Syncing()...0 sec [20090605-11:12:06.226909119] FFSB benchmark finished at: Fri Jun 5 11:12:05 2009 [20090605-11:12:06.230184372] [20090605-11:12:06.233525186] Results: [20090605-11:12:06.271688222] Benchmark took 310.10 sec [20090605-11:12:06.274376518] [20090605-11:12:06.277379371] Total Results [20090605-11:12:06.295943902] =============== [20090605-11:12:06.298917699] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090605-11:12:06.302211166] ======= ============ ========= ======= =========== ========== [20090605-11:12:06.305052383] readall : 52736000 170060.48 100.000% 100.000% 664MB/sec [20090605-11:12:06.307713174] - [20090605-11:12:06.310422608] 170060.48 Transactions per Second [20090605-11:12:06.313398794] [20090605-11:12:06.315958499] Throughput Results [20090605-11:12:06.333401917] =================== [20090605-11:12:06.336072733] Read Throughput: 664MB/sec [20090605-11:12:06.338863780] [20090605-11:12:06.341810255] System Call Latency statistics in millisecs [20090605-11:12:06.344417678] ===== [20090605-11:12:06.347165811] Min Avg Max Total Calls [20090605-11:12:06.349860998] ======== ======== ======== ============ [20090605-11:12:06.352155988] [ open] 0.006000 31.008712 862.916016 2060 [20090605-11:12:06.354573203] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:12:06.357995503] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:12:06.360626463] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:12:06.362968546] msec_range[3] 500.000000 - 1000.000000 : 38 [20090605-11:12:06.365251178] msec_range[4] 200.000000 - 500.000000 : 90 [20090605-11:12:06.367829761] msec_range[5] 100.000000 - 200.000000 : 36 [20090605-11:12:06.370503674] msec_range[6] 50.000000 - 100.000000 : 27 [20090605-11:12:06.372803593] msec_range[7] 20.000000 - 50.000000 : 112 [20090605-11:12:06.375023706] msec_range[8] 10.000000 - 20.000000 : 71 [20090605-11:12:06.377948167] msec_range[9] 5.000000 - 10.000000 : 24 [20090605-11:12:06.380599918] msec_range[10] 2.000000 - 5.000000 : 10 [20090605-11:12:06.383387959] msec_range[11] 1.000000 - 2.000000 : 2 [20090605-11:12:06.386073001] msec_range[12] 0.500000 - 1.000000 : 1 [20090605-11:12:06.388757705] msec_range[13] 0.200000 - 0.500000 : 3 [20090605-11:12:06.391576388] msec_range[14] 0.100000 - 0.200000 : 56 [20090605-11:12:06.394387407] msec_range[15] 0.050000 - 0.100000 : 479 [20090605-11:12:06.397133304] msec_range[16] 0.020000 - 0.050000 : 934 [20090605-11:12:06.399883931] msec_range[17] 0.010000 - 0.020000 : 92 [20090605-11:12:06.402709627] msec_range[18] 0.000000 - 0.010000 : 85 [20090605-11:12:06.405806344] [20090605-11:12:06.408402568] [ read] 0.001000 0.742623 1505.073975 52736000 [20090605-11:12:06.411089743] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:12:06.413418130] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:12:06.416006844] msec_range[2] 1000.000000 - 2000.000000 : 30 [20090605-11:12:06.418890274] msec_range[3] 500.000000 - 1000.000000 : 14030 [20090605-11:12:06.421577496] msec_range[4] 200.000000 - 500.000000 : 76489 [20090605-11:12:06.424041977] msec_range[5] 100.000000 - 200.000000 : 22927 [20090605-11:12:06.426404099] msec_range[6] 50.000000 - 100.000000 : 19471 [20090605-11:12:06.428951473] msec_range[7] 20.000000 - 50.000000 : 41563 [20090605-11:12:06.431621925] msec_range[8] 10.000000 - 20.000000 : 20843 [20090605-11:12:06.433955923] msec_range[9] 5.000000 - 10.000000 : 9988 [20090605-11:12:06.436340754] msec_range[10] 2.000000 - 5.000000 : 7271 [20090605-11:12:06.438857495] msec_range[11] 1.000000 - 2.000000 : 3026 [20090605-11:12:06.441509303] msec_range[12] 0.500000 - 1.000000 : 1989 [20090605-11:12:06.444178683] msec_range[13] 0.200000 - 0.500000 : 6611 [20090605-11:12:06.446881394] msec_range[14] 0.100000 - 0.200000 : 12078 [20090605-11:12:06.449603793] msec_range[15] 0.050000 - 0.100000 : 49349 [20090605-11:12:06.452543491] msec_range[16] 0.020000 - 0.050000 : 133572 [20090605-11:12:06.455141363] msec_range[17] 0.010000 - 0.020000 : 3211818 [20090605-11:12:06.457861089] msec_range[18] 0.000000 - 0.010000 : 49104945 [20090605-11:12:06.460487442] [20090605-11:12:06.463149289] [ close] 0.002000 0.008510 0.113000 2060 [20090605-11:12:06.466331504] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:12:06.469046327] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:12:06.471649683] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:12:06.474656556] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:12:06.477669985] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:12:06.480774955] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-11:12:06.483857585] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-11:12:06.486923431] msec_range[7] 20.000000 - 50.000000 : 0 [20090605-11:12:06.490113846] msec_range[8] 10.000000 - 20.000000 : 0 [20090605-11:12:06.492742217] msec_range[9] 5.000000 - 10.000000 : 0 [20090605-11:12:06.495379649] msec_range[10] 2.000000 - 5.000000 : 0 [20090605-11:12:06.498007326] msec_range[11] 1.000000 - 2.000000 : 0 [20090605-11:12:06.500563099] msec_range[12] 0.500000 - 1.000000 : 0 [20090605-11:12:06.503105870] msec_range[13] 0.200000 - 0.500000 : 0 [20090605-11:12:06.505822114] msec_range[14] 0.100000 - 0.200000 : 1 [20090605-11:12:06.508550971] msec_range[15] 0.050000 - 0.100000 : 2 [20090605-11:12:06.511248711] msec_range[16] 0.020000 - 0.050000 : 7 [20090605-11:12:06.515542384] msec_range[17] 0.010000 - 0.020000 : 503 [20090605-11:12:06.518610315] msec_range[18] 0.000000 - 0.010000 : 1547 [20090605-11:12:06.521254765] [20090605-11:12:06.524036311] [20090605-11:12:06.526884424] [20090605-11:12:06.529620588] [20090605-11:12:06.532173547] 11.6% User Time [20090605-11:12:06.534770830] 197.3% System Time [20090605-11:12:06.537455627] 209.0% CPU Utilization [20090605-11:12:06.540118280] Profilers reporting [20090605-11:12:23.119104362] Profilers postprocessing [20090605-11:12:23.383989665] Processing File : iostat.001 [20090605-11:12:23.386398385] Discovered iostat_interval=[5] [20090605-11:12:24.177998576] Processing Directory : sar.breakout.001 [20090605-11:12:24.180149604] Discovered sar_interval=[5] [20090605-11:12:24.360146319] Processing File : mpstat.001 [20090605-11:12:24.362381775] Discovered mpstat_interval=[5] [20090605-11:12:25.508765757] Stopping profiling. [20090605-11:12:25.514198012] Killing daemon. [20090605-11:12:27.795548082] Processing File : oprofile.001 [20090605-11:12:27.797786292] Processing File : oprofile-brief.001 [20090605-11:12:29.340916008] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-06-05_1047/btrfsnewformat-6-1-nodatacow' [20090605-11:12:33.318657952] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090605-11:12:35.931441999] PROCESSING COMMAND : 'mount -t btrfs -o nodatacow /dev/ffsbdev1 /mnt/ffsb1' [20090605-11:12:36.188562377] ONLY : Command [run random_reads__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb reuse=1 num_threads=1] found for me [20090605-11:12:36.241987543] PROCESSING COMMAND : 'run random_reads__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb reuse=1 num_threads=1' [20090605-11:12:36.292085085] new log requested [20090605-11:12:36.330934597] Running command ffsb [20090605-11:12:47.671072316] 06/05/2009-11:12:47 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb Succeeded [20090605-11:12:47.682213386] Importing argument : reuse=1 [20090605-11:12:47.695522287] Importing argument : num_threads=1 [20090605-11:12:47.723956467] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090605-11:12:47.811934155] FFSB version 6.0-RC2.1 started [20090605-11:12:47.814426543] [20090605-11:12:47.816688610] benchmark time = 300 [20090605-11:12:47.818961677] ThreadGroup 0 [20090605-11:12:47.820899665] ================ [20090605-11:12:47.822912018] num_threads = 1 [20090605-11:12:47.824837921] [20090605-11:12:47.826847631] read_random = on [20090605-11:12:47.828750350] read_size = 5242880 (5MB) [20090605-11:12:47.830704652] read_blocksize = 4096 (4KB) [20090605-11:12:47.832642965] read_skip = off [20090605-11:12:47.834680882] read_skipsize = 0 (0B) [20090605-11:12:47.836593661] [20090605-11:12:47.838563727] write_random = off [20090605-11:12:47.840471663] write_size = 0 (0B) [20090605-11:12:47.842488588] fsync_file = 0 [20090605-11:12:47.844377706] write_blocksize = 0 (0B) [20090605-11:12:47.846326002] wait time = 0 [20090605-11:12:47.848235898] [20090605-11:12:47.850274159] op weights [20090605-11:12:47.852174648] read = 1 (100.00%) [20090605-11:12:47.854115057] readall = 0 (0.00%) [20090605-11:12:47.856028610] write = 0 (0.00%) [20090605-11:12:47.858052229] create = 0 (0.00%) [20090605-11:12:47.859988009] append = 0 (0.00%) [20090605-11:12:47.861883403] delete = 0 (0.00%) [20090605-11:12:47.863850495] metaop = 0 (0.00%) [20090605-11:12:47.865867840] createdir = 0 (0.00%) [20090605-11:12:47.867748134] stat = 0 (0.00%) [20090605-11:12:47.869721636] writeall = 0 (0.00%) [20090605-11:12:47.872180086] writeall_fsync = 0 (0.00%) [20090605-11:12:47.874703402] open_close = 0 (0.00%) [20090605-11:12:47.877001211] write_fsync = 0 (0.00%) [20090605-11:12:47.879139120] create_fsync = 0 (0.00%) [20090605-11:12:47.881231239] append_fsync = 0 (0.00%) [20090605-11:12:47.883218162] [20090605-11:12:47.885239424] FileSystem /mnt/ffsb1 [20090605-11:12:47.887218320] ========== [20090605-11:12:47.889279604] num_dirs = 0 [20090605-11:12:47.891179584] starting files = 1024 [20090605-11:12:47.893133975] [20090605-11:12:47.895036952] min file size = 104857600 (100MB) [20090605-11:12:47.897085605] max file size = 104857600 (100MB) [20090605-11:12:47.899017453] directio = off [20090605-11:12:47.901006297] alignedio = on [20090605-11:12:47.902968396] bufferedio = off [20090605-11:12:47.905082194] [20090605-11:12:47.907079241] aging is off [20090605-11:12:47.909106412] current utilization = 4.47% [20090605-11:12:47.911080492] [20090605-11:12:47.913074365] checking existing fs: /mnt/ffsb1 [20090605-11:12:48.140133808] fs setup took 0 secs [20090605-11:12:48.579673763] Syncing()...0 sec [20090605-11:12:48.581691760] Starting Actual Benchmark At: Fri Jun 5 11:12:48 2009 [20090605-11:12:48.596773741] [20090605-11:17:49.741333765] Syncing()...0 sec [20090605-11:17:49.744592097] FFSB benchmark finished at: Fri Jun 5 11:17:49 2009 [20090605-11:17:49.747943073] [20090605-11:17:49.751301964] Results: [20090605-11:17:49.769490352] Benchmark took 301.16 sec [20090605-11:17:49.772292460] [20090605-11:17:49.775161595] Total Results [20090605-11:17:49.795096861] =============== [20090605-11:17:49.798015572] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090605-11:17:49.800748641] ======= ============ ========= ======= =========== ========== [20090605-11:17:49.803807866] read : 158720 527.03 100.000% 100.000% 2.06MB/sec [20090605-11:17:49.807863169] - [20090605-11:17:49.811266699] 527.03 Transactions per Second [20090605-11:17:49.814732029] [20090605-11:17:49.817586192] Throughput Results [20090605-11:17:49.836509181] =================== [20090605-11:17:49.839631381] Read Throughput: 2.06MB/sec [20090605-11:17:49.842725029] [20090605-11:17:49.845775314] System Call Latency statistics in millisecs [20090605-11:17:49.849837636] ===== [20090605-11:17:49.853024732] Min Avg Max Total Calls [20090605-11:17:49.857303545] ======== ======== ======== ============ [20090605-11:17:49.860449864] [ open] 0.012000 0.021758 0.033000 124 [20090605-11:17:49.863624282] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:17:49.866489888] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:17:49.869785577] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:17:49.872800649] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:17:49.875850130] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:17:49.880687236] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-11:17:49.883689536] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-11:17:49.886532726] msec_range[7] 20.000000 - 50.000000 : 0 [20090605-11:17:49.889606183] msec_range[8] 10.000000 - 20.000000 : 0 [20090605-11:17:49.893053456] msec_range[9] 5.000000 - 10.000000 : 0 [20090605-11:17:49.896178873] msec_range[10] 2.000000 - 5.000000 : 0 [20090605-11:17:49.899141538] msec_range[11] 1.000000 - 2.000000 : 0 [20090605-11:17:49.901837664] msec_range[12] 0.500000 - 1.000000 : 0 [20090605-11:17:49.904616624] msec_range[13] 0.200000 - 0.500000 : 0 [20090605-11:17:49.907247068] msec_range[14] 0.100000 - 0.200000 : 0 [20090605-11:17:49.909932083] msec_range[15] 0.050000 - 0.100000 : 0 [20090605-11:17:49.913502076] msec_range[16] 0.020000 - 0.050000 : 84 [20090605-11:17:49.917231803] msec_range[17] 0.010000 - 0.020000 : 40 [20090605-11:17:49.920539497] msec_range[18] 0.000000 - 0.010000 : 0 [20090605-11:17:49.923549029] [20090605-11:17:49.926588823] [ read] 0.002000 1.891534 33.751999 158720 [20090605-11:17:49.931366640] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:17:49.935696740] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:17:49.938751071] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:17:49.941820217] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:17:49.944648983] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:17:49.947745721] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-11:17:49.951031491] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-11:17:49.955244065] msec_range[7] 20.000000 - 50.000000 : 58 [20090605-11:17:49.958307857] msec_range[8] 10.000000 - 20.000000 : 602 [20090605-11:17:49.961480140] msec_range[9] 5.000000 - 10.000000 : 13303 [20090605-11:17:49.964828562] msec_range[10] 2.000000 - 5.000000 : 44830 [20090605-11:17:49.967799684] msec_range[11] 1.000000 - 2.000000 : 9520 [20090605-11:17:49.970599352] msec_range[12] 0.500000 - 1.000000 : 568 [20090605-11:17:49.973427126] msec_range[13] 0.200000 - 0.500000 : 84738 [20090605-11:17:49.976523160] msec_range[14] 0.100000 - 0.200000 : 477 [20090605-11:17:49.980632868] msec_range[15] 0.050000 - 0.100000 : 0 [20090605-11:17:49.983670926] msec_range[16] 0.020000 - 0.050000 : 6 [20090605-11:17:49.986626492] msec_range[17] 0.010000 - 0.020000 : 590 [20090605-11:17:49.989294316] msec_range[18] 0.000000 - 0.010000 : 4028 [20090605-11:17:49.991888891] [20090605-11:17:49.994784554] [ lseek] 0.000000 0.001479 0.183000 158720 [20090605-11:17:49.998008382] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:17:50.001027357] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:17:50.006661177] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:17:50.009894648] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:17:50.012989097] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:17:50.016498030] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-11:17:50.019604058] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-11:17:50.022782145] msec_range[7] 20.000000 - 50.000000 : 0 [20090605-11:17:50.025838107] msec_range[8] 10.000000 - 20.000000 : 0 [20090605-11:17:50.029274441] msec_range[9] 5.000000 - 10.000000 : 0 [20090605-11:17:50.034681766] msec_range[10] 2.000000 - 5.000000 : 0 [20090605-11:17:50.037488725] msec_range[11] 1.000000 - 2.000000 : 0 [20090605-11:17:50.040474909] msec_range[12] 0.500000 - 1.000000 : 0 [20090605-11:17:50.043763244] msec_range[13] 0.200000 - 0.500000 : 0 [20090605-11:17:50.046539846] msec_range[14] 0.100000 - 0.200000 : 1 [20090605-11:17:50.049562595] msec_range[15] 0.050000 - 0.100000 : 2 [20090605-11:17:50.052500572] msec_range[16] 0.020000 - 0.050000 : 4 [20090605-11:17:50.055406265] msec_range[17] 0.010000 - 0.020000 : 72 [20090605-11:17:50.058112277] msec_range[18] 0.000000 - 0.010000 : 158641 [20090605-11:17:50.060970408] [20090605-11:17:50.064323500] [ close] 0.003000 0.006008 0.013000 124 [20090605-11:17:50.067265650] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:17:50.070358326] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:17:50.073327862] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:17:50.076190081] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:17:50.079160609] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:17:50.082067100] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-11:17:50.084734085] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-11:17:50.087535915] msec_range[7] 20.000000 - 50.000000 : 0 [20090605-11:17:50.090863294] msec_range[8] 10.000000 - 20.000000 : 0 [20090605-11:17:50.093688502] msec_range[9] 5.000000 - 10.000000 : 0 [20090605-11:17:50.096695076] msec_range[10] 2.000000 - 5.000000 : 0 [20090605-11:17:50.099636725] msec_range[11] 1.000000 - 2.000000 : 0 [20090605-11:17:50.102283504] msec_range[12] 0.500000 - 1.000000 : 0 [20090605-11:17:50.104974171] msec_range[13] 0.200000 - 0.500000 : 0 [20090605-11:17:50.107582586] msec_range[14] 0.100000 - 0.200000 : 0 [20090605-11:17:50.110127403] msec_range[15] 0.050000 - 0.100000 : 0 [20090605-11:17:50.112854970] msec_range[16] 0.020000 - 0.050000 : 0 [20090605-11:17:50.115482211] msec_range[17] 0.010000 - 0.020000 : 9 [20090605-11:17:50.118008368] msec_range[18] 0.000000 - 0.010000 : 115 [20090605-11:17:50.120677488] [20090605-11:17:50.123451539] [20090605-11:17:50.125979595] [20090605-11:17:50.128590658] [20090605-11:17:50.131313459] 0.1% User Time [20090605-11:17:50.133794888] 2.1% System Time [20090605-11:17:50.136591787] 2.3% CPU Utilization [20090605-11:17:50.139268662] Profilers reporting [20090605-11:17:50.141877874] /autobench/scripts/doprofilers: line 2: 851 Terminated ${CMDS[$i]} [20090605-11:17:50.144490520] /autobench/scripts/doprofilers: line 2: 888 Terminated ${CMDS[$i]} [20090605-11:18:03.397275836] Profilers postprocessing [20090605-11:18:03.517074709] Processing File : iostat.001 [20090605-11:18:03.519724018] Discovered iostat_interval=[5] [20090605-11:18:04.242833568] Processing Directory : sar.breakout.001 [20090605-11:18:04.245042252] Discovered sar_interval=[5] [20090605-11:18:04.415453993] Processing File : mpstat.001 [20090605-11:18:04.419987422] Discovered mpstat_interval=[5] [20090605-11:18:05.562949926] Stopping profiling. [20090605-11:18:05.569772434] Killing daemon. [20090605-11:18:07.792324459] Processing File : oprofile.001 [20090605-11:18:07.794688535] Processing File : oprofile-brief.001 [20090605-11:18:08.600988972] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-06-05_1047/btrfsnewformat-6-1-nodatacow' [20090605-11:18:11.268573190] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090605-11:18:11.876382825] PROCESSING COMMAND : 'mount -t btrfs -o nodatacow /dev/ffsbdev1 /mnt/ffsb1' [20090605-11:18:12.131537163] ONLY : Command [run random_reads__threads_0016 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb reuse=1 num_threads=16] found for me [20090605-11:18:12.184606428] PROCESSING COMMAND : 'run random_reads__threads_0016 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb reuse=1 num_threads=16' [20090605-11:18:12.232885532] new log requested [20090605-11:18:12.263651184] Running command ffsb [20090605-11:18:22.159397905] 06/05/2009-11:18:22 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb Succeeded [20090605-11:18:22.170592564] Importing argument : reuse=1 [20090605-11:18:22.183958692] Importing argument : num_threads=16 [20090605-11:18:22.212706857] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090605-11:18:22.287915817] FFSB version 6.0-RC2.1 started [20090605-11:18:22.290303561] [20090605-11:18:22.354063580] benchmark time = 300 [20090605-11:18:22.356043620] ThreadGroup 0 [20090605-11:18:22.358214404] ================ [20090605-11:18:22.360482262] num_threads = 16 [20090605-11:18:22.362828454] [20090605-11:18:22.365015913] read_random = on [20090605-11:18:22.366941501] read_size = 5242880 (5MB) [20090605-11:18:22.368992919] read_blocksize = 4096 (4KB) [20090605-11:18:22.370958674] read_skip = off [20090605-11:18:22.372978870] read_skipsize = 0 (0B) [20090605-11:18:22.374894636] [20090605-11:18:22.376902939] write_random = off [20090605-11:18:22.378863207] write_size = 0 (0B) [20090605-11:18:22.380893530] fsync_file = 0 [20090605-11:18:22.382777294] write_blocksize = 0 (0B) [20090605-11:18:22.384736297] wait time = 0 [20090605-11:18:22.386666975] [20090605-11:18:22.388705467] op weights [20090605-11:18:22.390577916] read = 1 (100.00%) [20090605-11:18:22.392529711] readall = 0 (0.00%) [20090605-11:18:22.394434954] write = 0 (0.00%) [20090605-11:18:22.396452327] create = 0 (0.00%) [20090605-11:18:22.398332597] append = 0 (0.00%) [20090605-11:18:22.400260893] delete = 0 (0.00%) [20090605-11:18:22.402337998] metaop = 0 (0.00%) [20090605-11:18:22.404479313] createdir = 0 (0.00%) [20090605-11:18:22.406506274] stat = 0 (0.00%) [20090605-11:18:22.408483363] writeall = 0 (0.00%) [20090605-11:18:22.410563888] writeall_fsync = 0 (0.00%) [20090605-11:18:22.412489172] open_close = 0 (0.00%) [20090605-11:18:22.414407158] write_fsync = 0 (0.00%) [20090605-11:18:22.416354365] create_fsync = 0 (0.00%) [20090605-11:18:22.418404391] append_fsync = 0 (0.00%) [20090605-11:18:22.420303038] [20090605-11:18:22.422264025] FileSystem /mnt/ffsb1 [20090605-11:18:22.424161114] ========== [20090605-11:18:22.426197717] num_dirs = 0 [20090605-11:18:22.428424674] starting files = 1024 [20090605-11:18:22.430604671] [20090605-11:18:22.432643838] min file size = 104857600 (100MB) [20090605-11:18:22.434620252] max file size = 104857600 (100MB) [20090605-11:18:22.436672634] directio = off [20090605-11:18:22.438671906] alignedio = on [20090605-11:18:22.440706303] bufferedio = off [20090605-11:18:22.442596859] [20090605-11:18:22.444634915] aging is off [20090605-11:18:22.446645064] current utilization = 4.47% [20090605-11:18:22.448516738] [20090605-11:18:22.450510425] checking existing fs: /mnt/ffsb1 [20090605-11:18:22.630667616] fs setup took 0 secs [20090605-11:18:23.689588947] Syncing()...1 sec [20090605-11:18:23.691838288] Starting Actual Benchmark At: Fri Jun 5 11:18:23 2009 [20090605-11:18:23.708993201] [20090605-11:23:28.843113413] Syncing()...0 sec [20090605-11:23:28.854850678] FFSB benchmark finished at: Fri Jun 5 11:23:28 2009 [20090605-11:23:28.858097926] [20090605-11:23:28.861369015] Results: [20090605-11:23:28.888314241] Benchmark took 305.09 sec [20090605-11:23:28.892047887] [20090605-11:23:28.895645245] Total Results [20090605-11:23:28.914895805] =============== [20090605-11:23:28.918844762] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090605-11:23:28.921882144] ======= ============ ========= ======= =========== ========== [20090605-11:23:28.925771291] read : 1468160 4812.21 100.000% 100.000% 18.8MB/sec [20090605-11:23:28.929816084] - [20090605-11:23:28.935205198] 4812.21 Transactions per Second [20090605-11:23:28.938280088] [20090605-11:23:28.941664743] Throughput Results [20090605-11:23:28.959512820] =================== [20090605-11:23:28.962408189] Read Throughput: 18.8MB/sec [20090605-11:23:28.965216696] [20090605-11:23:28.968378616] System Call Latency statistics in millisecs [20090605-11:23:28.971367401] ===== [20090605-11:23:28.974431306] Min Avg Max Total Calls [20090605-11:23:28.977456017] ======== ======== ======== ============ [20090605-11:23:28.981218125] [ open] 0.006000 0.026379 0.225000 1147 [20090605-11:23:28.984172507] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:23:28.987632165] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:23:28.991682700] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:23:28.995730506] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:23:28.999076837] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:23:29.002696126] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-11:23:29.006080625] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-11:23:29.009576854] msec_range[7] 20.000000 - 50.000000 : 0 [20090605-11:23:29.012689317] msec_range[8] 10.000000 - 20.000000 : 0 [20090605-11:23:29.015759492] msec_range[9] 5.000000 - 10.000000 : 0 [20090605-11:23:29.018696488] msec_range[10] 2.000000 - 5.000000 : 0 [20090605-11:23:29.022064917] msec_range[11] 1.000000 - 2.000000 : 0 [20090605-11:23:29.025479390] msec_range[12] 0.500000 - 1.000000 : 0 [20090605-11:23:29.028987362] msec_range[13] 0.200000 - 0.500000 : 1 [20090605-11:23:29.033002347] msec_range[14] 0.100000 - 0.200000 : 0 [20090605-11:23:29.036164290] msec_range[15] 0.050000 - 0.100000 : 115 [20090605-11:23:29.039901744] msec_range[16] 0.020000 - 0.050000 : 820 [20090605-11:23:29.042964150] msec_range[17] 0.010000 - 0.020000 : 185 [20090605-11:23:29.045724174] msec_range[18] 0.000000 - 0.010000 : 26 [20090605-11:23:29.048456419] [20090605-11:23:29.051101231] [ read] 0.001000 3.298732 113.987999 1468160 [20090605-11:23:29.053829119] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:23:29.057136598] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:23:29.060326066] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:23:29.063774336] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:23:29.066924175] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:23:29.070325899] msec_range[5] 100.000000 - 200.000000 : 4 [20090605-11:23:29.073573664] msec_range[6] 50.000000 - 100.000000 : 7 [20090605-11:23:29.076827352] msec_range[7] 20.000000 - 50.000000 : 123 [20090605-11:23:29.079879439] msec_range[8] 10.000000 - 20.000000 : 6448 [20090605-11:23:29.085830337] msec_range[9] 5.000000 - 10.000000 : 313979 [20090605-11:23:29.088721955] msec_range[10] 2.000000 - 5.000000 : 755186 [20090605-11:23:29.092243819] msec_range[11] 1.000000 - 2.000000 : 57666 [20090605-11:23:29.095518652] msec_range[12] 0.500000 - 1.000000 : 10001 [20090605-11:23:29.100412245] msec_range[13] 0.200000 - 0.500000 : 250792 [20090605-11:23:29.103441581] msec_range[14] 0.100000 - 0.200000 : 515 [20090605-11:23:29.106667175] msec_range[15] 0.050000 - 0.100000 : 34 [20090605-11:23:29.109733049] msec_range[16] 0.020000 - 0.050000 : 347 [20090605-11:23:29.112801070] msec_range[17] 0.010000 - 0.020000 : 14503 [20090605-11:23:29.116029401] msec_range[18] 0.000000 - 0.010000 : 58555 [20090605-11:23:29.119086195] [20090605-11:23:29.122400662] [ lseek] 0.000000 0.001655 0.463000 1468160 [20090605-11:23:29.125541449] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:23:29.128803470] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:23:29.131910752] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:23:29.135453159] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:23:29.139231232] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:23:29.142358736] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-11:23:29.145353103] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-11:23:29.148659135] msec_range[7] 20.000000 - 50.000000 : 0 [20090605-11:23:29.151599632] msec_range[8] 10.000000 - 20.000000 : 0 [20090605-11:23:29.154514664] msec_range[9] 5.000000 - 10.000000 : 0 [20090605-11:23:29.157599860] msec_range[10] 2.000000 - 5.000000 : 0 [20090605-11:23:29.160742407] msec_range[11] 1.000000 - 2.000000 : 0 [20090605-11:23:29.163878859] msec_range[12] 0.500000 - 1.000000 : 0 [20090605-11:23:29.167270429] msec_range[13] 0.200000 - 0.500000 : 30 [20090605-11:23:29.170323498] msec_range[14] 0.100000 - 0.200000 : 4 [20090605-11:23:29.173407678] msec_range[15] 0.050000 - 0.100000 : 177 [20090605-11:23:29.176685575] msec_range[16] 0.020000 - 0.050000 : 630 [20090605-11:23:29.179871640] msec_range[17] 0.010000 - 0.020000 : 1301 [20090605-11:23:29.182636329] msec_range[18] 0.000000 - 0.010000 : 1466018 [20090605-11:23:29.185593918] [20090605-11:23:29.188721626] [ close] 0.002000 0.006666 0.060000 1147 [20090605-11:23:29.191685132] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:23:29.194829300] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:23:29.197800253] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:23:29.200695579] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:23:29.203752797] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:23:29.206464331] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-11:23:29.209362817] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-11:23:29.212385337] msec_range[7] 20.000000 - 50.000000 : 0 [20090605-11:23:29.216710468] msec_range[8] 10.000000 - 20.000000 : 0 [20090605-11:23:29.219804287] msec_range[9] 5.000000 - 10.000000 : 0 [20090605-11:23:29.223254044] msec_range[10] 2.000000 - 5.000000 : 0 [20090605-11:23:29.226638703] msec_range[11] 1.000000 - 2.000000 : 0 [20090605-11:23:29.231147129] msec_range[12] 0.500000 - 1.000000 : 0 [20090605-11:23:29.236384862] msec_range[13] 0.200000 - 0.500000 : 0 [20090605-11:23:29.239557643] msec_range[14] 0.100000 - 0.200000 : 0 [20090605-11:23:29.242911323] msec_range[15] 0.050000 - 0.100000 : 1 [20090605-11:23:29.247439231] msec_range[16] 0.020000 - 0.050000 : 3 [20090605-11:23:29.251053912] msec_range[17] 0.010000 - 0.020000 : 149 [20090605-11:23:29.255040801] msec_range[18] 0.000000 - 0.010000 : 994 [20090605-11:23:29.258294842] [20090605-11:23:29.261289257] [20090605-11:23:29.264162152] [20090605-11:23:29.267128602] [20090605-11:23:29.270438429] 1.3% User Time [20090605-11:23:29.273326205] 23.0% System Time [20090605-11:23:29.276269309] 24.3% CPU Utilization [20090605-11:23:29.279226931] Profilers reporting [20090605-11:23:43.200397310] Profilers postprocessing [20090605-11:23:43.391049711] Processing File : iostat.001 [20090605-11:23:43.393581778] Discovered iostat_interval=[5] [20090605-11:23:44.152550702] Processing Directory : sar.breakout.001 [20090605-11:23:44.154609782] Discovered sar_interval=[5] [20090605-11:23:44.327439846] Processing File : mpstat.001 [20090605-11:23:44.329676552] Discovered mpstat_interval=[5] [20090605-11:23:45.473992470] Stopping profiling. [20090605-11:23:45.480918551] Killing daemon. [20090605-11:23:46.692844258] Processing File : oprofile.001 [20090605-11:23:46.695151440] Processing File : oprofile-brief.001 [20090605-11:23:47.782290546] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-06-05_1047/btrfsnewformat-6-1-nodatacow' [20090605-11:23:51.292431032] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090605-11:23:54.595918262] PROCESSING COMMAND : 'mount -t btrfs -o nodatacow /dev/ffsbdev1 /mnt/ffsb1' [20090605-11:23:54.831053027] ONLY : Command [run random_reads__threads_0128 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb reuse=1 num_threads=128] found for me [20090605-11:23:54.885626033] PROCESSING COMMAND : 'run random_reads__threads_0128 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb reuse=1 num_threads=128' [20090605-11:23:54.935054625] new log requested [20090605-11:23:54.965854380] Running command ffsb [20090605-11:24:05.312616172] 06/05/2009-11:24:05 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb Succeeded [20090605-11:24:05.323780095] Importing argument : reuse=1 [20090605-11:24:05.337673825] Importing argument : num_threads=128 [20090605-11:24:05.366417171] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090605-11:24:05.456131643] FFSB version 6.0-RC2.1 started [20090605-11:24:05.458511677] [20090605-11:24:05.985316950] benchmark time = 300 [20090605-11:24:05.987488008] ThreadGroup 0 [20090605-11:24:05.989563935] ================ [20090605-11:24:05.991729861] num_threads = 128 [20090605-11:24:05.994167947] [20090605-11:24:05.996289710] read_random = on [20090605-11:24:05.998209142] read_size = 5242880 (5MB) [20090605-11:24:06.000219439] read_blocksize = 4096 (4KB) [20090605-11:24:06.002234555] read_skip = off [20090605-11:24:06.004243149] read_skipsize = 0 (0B) [20090605-11:24:06.006159431] [20090605-11:24:06.008175631] write_random = off [20090605-11:24:06.010188522] write_size = 0 (0B) [20090605-11:24:06.012205671] fsync_file = 0 [20090605-11:24:06.014084013] write_blocksize = 0 (0B) [20090605-11:24:06.016088063] wait time = 0 [20090605-11:24:06.018068616] [20090605-11:24:06.020091195] op weights [20090605-11:24:06.021971283] read = 1 (100.00%) [20090605-11:24:06.023952831] readall = 0 (0.00%) [20090605-11:24:06.025927509] write = 0 (0.00%) [20090605-11:24:06.027956940] create = 0 (0.00%) [20090605-11:24:06.029871213] append = 0 (0.00%) [20090605-11:24:06.031781358] delete = 0 (0.00%) [20090605-11:24:06.033767175] metaop = 0 (0.00%) [20090605-11:24:06.035810925] createdir = 0 (0.00%) [20090605-11:24:06.037697972] stat = 0 (0.00%) [20090605-11:24:06.039884131] writeall = 0 (0.00%) [20090605-11:24:06.042028371] writeall_fsync = 0 (0.00%) [20090605-11:24:06.043891684] open_close = 0 (0.00%) [20090605-11:24:06.045886608] write_fsync = 0 (0.00%) [20090605-11:24:06.047940825] create_fsync = 0 (0.00%) [20090605-11:24:06.049963788] append_fsync = 0 (0.00%) [20090605-11:24:06.051902680] [20090605-11:24:06.053925322] FileSystem /mnt/ffsb1 [20090605-11:24:06.055902625] ========== [20090605-11:24:06.057830888] num_dirs = 0 [20090605-11:24:06.059702976] starting files = 1024 [20090605-11:24:06.061714746] [20090605-11:24:06.063687963] min file size = 104857600 (100MB) [20090605-11:24:06.065694325] max file size = 104857600 (100MB) [20090605-11:24:06.067597864] directio = off [20090605-11:24:06.069580311] alignedio = on [20090605-11:24:06.071879612] bufferedio = off [20090605-11:24:06.074186296] [20090605-11:24:06.076425600] aging is off [20090605-11:24:06.078505082] current utilization = 4.47% [20090605-11:24:06.080587532] [20090605-11:24:06.082555767] checking existing fs: /mnt/ffsb1 [20090605-11:24:06.285917768] fs setup took 0 secs [20090605-11:24:06.779219222] Syncing()...0 sec [20090605-11:24:06.786119637] Starting Actual Benchmark At: Fri Jun 5 11:24:06 2009 [20090605-11:24:06.801911965] [20090605-11:29:14.558339688] Syncing()...0 sec [20090605-11:29:14.600155072] FFSB benchmark finished at: Fri Jun 5 11:29:14 2009 [20090605-11:29:14.603534549] [20090605-11:29:14.606891879] Results: [20090605-11:29:14.680572108] Benchmark took 307.33 sec [20090605-11:29:14.683745642] [20090605-11:29:14.686983813] Total Results [20090605-11:29:14.704935664] =============== [20090605-11:29:14.707768499] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090605-11:29:14.710553110] ======= ============ ========= ======= =========== ========== [20090605-11:29:14.713339615] read : 6837760 22248.80 100.000% 100.000% 86.9MB/sec [20090605-11:29:14.716590136] - [20090605-11:29:14.719883680] 22248.80 Transactions per Second [20090605-11:29:14.722520610] [20090605-11:29:14.725273157] Throughput Results [20090605-11:29:14.743143333] =================== [20090605-11:29:14.745903768] Read Throughput: 86.9MB/sec [20090605-11:29:14.748729503] [20090605-11:29:14.751574079] System Call Latency statistics in millisecs [20090605-11:29:14.754407158] ===== [20090605-11:29:14.757559110] Min Avg Max Total Calls [20090605-11:29:14.760087337] ======== ======== ======== ============ [20090605-11:29:14.762974746] [ open] 0.006000 0.047764 17.850000 5342 [20090605-11:29:14.765868393] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:29:14.768847069] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:29:14.771442786] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:29:14.773995199] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:29:14.776625677] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:29:14.779275430] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-11:29:14.781875183] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-11:29:14.784579383] msec_range[7] 20.000000 - 50.000000 : 0 [20090605-11:29:14.787168256] msec_range[8] 10.000000 - 20.000000 : 2 [20090605-11:29:14.789801484] msec_range[9] 5.000000 - 10.000000 : 5 [20090605-11:29:14.792333740] msec_range[10] 2.000000 - 5.000000 : 2 [20090605-11:29:14.794860371] msec_range[11] 1.000000 - 2.000000 : 0 [20090605-11:29:14.797460700] msec_range[12] 0.500000 - 1.000000 : 0 [20090605-11:29:14.800067255] msec_range[13] 0.200000 - 0.500000 : 1 [20090605-11:29:14.802528061] msec_range[14] 0.100000 - 0.200000 : 69 [20090605-11:29:14.805096077] msec_range[15] 0.050000 - 0.100000 : 1220 [20090605-11:29:14.807958310] msec_range[16] 0.020000 - 0.050000 : 3152 [20090605-11:29:14.810625761] msec_range[17] 0.010000 - 0.020000 : 736 [20090605-11:29:14.813150854] msec_range[18] 0.000000 - 0.010000 : 155 [20090605-11:29:14.815734167] [20090605-11:29:14.818361226] [ read] 0.001000 5.689275 254.871994 6837760 [20090605-11:29:14.820976171] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:29:14.823470386] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:29:14.826029480] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:29:14.828568208] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:29:14.831303710] msec_range[4] 200.000000 - 500.000000 : 4 [20090605-11:29:14.834008422] msec_range[5] 100.000000 - 200.000000 : 60 [20090605-11:29:14.836840400] msec_range[6] 50.000000 - 100.000000 : 247 [20090605-11:29:14.839568243] msec_range[7] 20.000000 - 50.000000 : 45133 [20090605-11:29:14.842232962] msec_range[8] 10.000000 - 20.000000 : 608659 [20090605-11:29:14.844956210] msec_range[9] 5.000000 - 10.000000 : 2931248 [20090605-11:29:14.847615719] msec_range[10] 2.000000 - 5.000000 : 2692977 [20090605-11:29:14.850283666] msec_range[11] 1.000000 - 2.000000 : 111948 [20090605-11:29:14.852911021] msec_range[12] 0.500000 - 1.000000 : 21769 [20090605-11:29:14.855427521] msec_range[13] 0.200000 - 0.500000 : 25252 [20090605-11:29:14.858017177] msec_range[14] 0.100000 - 0.200000 : 358 [20090605-11:29:14.860762320] msec_range[15] 0.050000 - 0.100000 : 852 [20090605-11:29:14.863514679] msec_range[16] 0.020000 - 0.050000 : 6341 [20090605-11:29:14.866153485] msec_range[17] 0.010000 - 0.020000 : 60309 [20090605-11:29:14.868752059] msec_range[18] 0.000000 - 0.010000 : 332603 [20090605-11:29:14.871531663] [20090605-11:29:14.874161487] [ lseek] 0.000000 0.001836 0.561000 6837760 [20090605-11:29:14.876763702] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:29:14.879451500] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:29:14.882166323] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:29:14.885173085] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:29:14.888426599] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:29:14.891025385] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-11:29:14.893969564] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-11:29:14.897649090] msec_range[7] 20.000000 - 50.000000 : 0 [20090605-11:29:14.901338035] msec_range[8] 10.000000 - 20.000000 : 0 [20090605-11:29:14.904389222] msec_range[9] 5.000000 - 10.000000 : 0 [20090605-11:29:14.907359265] msec_range[10] 2.000000 - 5.000000 : 0 [20090605-11:29:14.910414783] msec_range[11] 1.000000 - 2.000000 : 0 [20090605-11:29:14.913249110] msec_range[12] 0.500000 - 1.000000 : 4 [20090605-11:29:14.915943565] msec_range[13] 0.200000 - 0.500000 : 84 [20090605-11:29:14.919330936] msec_range[14] 0.100000 - 0.200000 : 543 [20090605-11:29:14.922061966] msec_range[15] 0.050000 - 0.100000 : 3590 [20090605-11:29:14.924539055] msec_range[16] 0.020000 - 0.050000 : 11388 [20090605-11:29:14.927189811] msec_range[17] 0.010000 - 0.020000 : 14969 [20090605-11:29:14.929864737] msec_range[18] 0.000000 - 0.010000 : 6807182 [20090605-11:29:14.932762497] [20090605-11:29:14.935211190] [ close] 0.002000 0.007121 0.133000 5342 [20090605-11:29:14.937759887] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:29:14.940346560] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:29:14.943024813] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:29:14.946253483] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:29:14.949377773] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:29:14.952321953] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-11:29:14.954938876] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-11:29:14.957545271] msec_range[7] 20.000000 - 50.000000 : 0 [20090605-11:29:14.960044650] msec_range[8] 10.000000 - 20.000000 : 0 [20090605-11:29:14.962671006] msec_range[9] 5.000000 - 10.000000 : 0 [20090605-11:29:14.965207261] msec_range[10] 2.000000 - 5.000000 : 0 [20090605-11:29:14.967843425] msec_range[11] 1.000000 - 2.000000 : 0 [20090605-11:29:14.970500650] msec_range[12] 0.500000 - 1.000000 : 0 [20090605-11:29:14.973030350] msec_range[13] 0.200000 - 0.500000 : 0 [20090605-11:29:14.975477245] msec_range[14] 0.100000 - 0.200000 : 2 [20090605-11:29:14.978117399] msec_range[15] 0.050000 - 0.100000 : 11 [20090605-11:29:14.980809459] msec_range[16] 0.020000 - 0.050000 : 61 [20090605-11:29:14.983377473] msec_range[17] 0.010000 - 0.020000 : 482 [20090605-11:29:14.985897410] msec_range[18] 0.000000 - 0.010000 : 4786 [20090605-11:29:14.988574344] [20090605-11:29:14.991235362] [20090605-11:29:14.994328944] [20090605-11:29:14.997335411] [20090605-11:29:15.000242750] 6.4% User Time [20090605-11:29:15.003141205] 116.2% System Time [20090605-11:29:15.005774726] 122.6% CPU Utilization [20090605-11:29:15.008519055] Profilers reporting [20090605-11:29:33.431770539] Profilers postprocessing [20090605-11:29:33.686457423] Processing File : iostat.001 [20090605-11:29:33.688705704] Discovered iostat_interval=[5] [20090605-11:29:34.472759853] Processing Directory : sar.breakout.001 [20090605-11:29:34.474873676] Discovered sar_interval=[5] [20090605-11:29:34.649997025] Processing File : mpstat.001 [20090605-11:29:34.652241923] Discovered mpstat_interval=[5] [20090605-11:29:35.798505394] Stopping profiling. [20090605-11:29:35.803689897] Killing daemon. [20090605-11:29:38.091230228] Processing File : oprofile.001 [20090605-11:29:38.093401991] Processing File : oprofile-brief.001 [20090605-11:29:39.663192081] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-06-05_1047/btrfsnewformat-6-1-nodatacow' [20090605-11:29:43.426141079] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090605-11:29:47.469938800] PROCESSING COMMAND : 'mount -t btrfs -o nodatacow /dev/ffsbdev1 /mnt/ffsb1' [20090605-11:29:47.697277645] ONLY : Command [run random_writes__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb reuse=1 num_threads=1] found for me [20090605-11:29:47.752751334] PROCESSING COMMAND : 'run random_writes__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb reuse=1 num_threads=1' [20090605-11:29:47.801882802] new log requested [20090605-11:29:47.832975634] Running command ffsb [20090605-11:29:59.047284362] 06/05/2009-11:29:59 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb Succeeded [20090605-11:29:59.058812187] Importing argument : reuse=1 [20090605-11:29:59.072415248] Importing argument : num_threads=1 [20090605-11:29:59.100582611] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090605-11:29:59.191878035] FFSB version 6.0-RC2.1 started [20090605-11:29:59.194201188] [20090605-11:29:59.196572879] benchmark time = 300 [20090605-11:29:59.198768010] ThreadGroup 0 [20090605-11:29:59.200871361] ================ [20090605-11:29:59.202798079] num_threads = 1 [20090605-11:29:59.204779057] [20090605-11:29:59.206725221] read_random = off [20090605-11:29:59.208917472] read_size = 0 (0B) [20090605-11:29:59.210940567] read_blocksize = 0 (0B) [20090605-11:29:59.212900316] read_skip = off [20090605-11:29:59.214836405] read_skipsize = 0 (0B) [20090605-11:29:59.216957891] [20090605-11:29:59.218896531] write_random = on [20090605-11:29:59.220863789] write_size = 5242880 (5MB) [20090605-11:29:59.222798397] fsync_file = 0 [20090605-11:29:59.224819508] write_blocksize = 4096 (4KB) [20090605-11:29:59.226721600] wait time = 0 [20090605-11:29:59.228611463] [20090605-11:29:59.230547445] op weights [20090605-11:29:59.232603792] read = 0 (0.00%) [20090605-11:29:59.234588838] readall = 0 (0.00%) [20090605-11:29:59.236559607] write = 1 (100.00%) [20090605-11:29:59.238489497] create = 0 (0.00%) [20090605-11:29:59.240423704] append = 0 (0.00%) [20090605-11:29:59.242354975] delete = 0 (0.00%) [20090605-11:29:59.244372264] metaop = 0 (0.00%) [20090605-11:29:59.246708822] createdir = 0 (0.00%) [20090605-11:29:59.248737541] stat = 0 (0.00%) [20090605-11:29:59.250740317] writeall = 0 (0.00%) [20090605-11:29:59.252688024] writeall_fsync = 0 (0.00%) [20090605-11:29:59.254937273] open_close = 0 (0.00%) [20090605-11:29:59.256882370] write_fsync = 0 (0.00%) [20090605-11:29:59.258816035] create_fsync = 0 (0.00%) [20090605-11:29:59.260754689] append_fsync = 0 (0.00%) [20090605-11:29:59.262717331] [20090605-11:29:59.264685998] FileSystem /mnt/ffsb1 [20090605-11:29:59.266621290] ========== [20090605-11:29:59.268595280] num_dirs = 0 [20090605-11:29:59.270736056] starting files = 1024 [20090605-11:29:59.272940258] [20090605-11:29:59.274861393] min file size = 104857600 (100MB) [20090605-11:29:59.276756716] max file size = 104857600 (100MB) [20090605-11:29:59.278780306] directio = off [20090605-11:29:59.280727444] alignedio = on [20090605-11:29:59.282678591] bufferedio = off [20090605-11:29:59.284570153] [20090605-11:29:59.286622780] aging is off [20090605-11:29:59.288553834] current utilization = 4.47% [20090605-11:29:59.290528172] [20090605-11:29:59.292431656] checking existing fs: /mnt/ffsb1 [20090605-11:29:59.511770072] fs setup took 0 secs [20090605-11:29:59.882893691] Syncing()...0 sec [20090605-11:29:59.885104580] Starting Actual Benchmark At: Fri Jun 5 11:29:59 2009 [20090605-11:29:59.900492669] [20090605-11:35:07.066320222] Syncing()...6 sec [20090605-11:35:07.120179752] FFSB benchmark finished at: Fri Jun 5 11:35:06 2009 [20090605-11:35:07.123732324] [20090605-11:35:07.127153156] Results: [20090605-11:35:07.188683854] Benchmark took 306.68 sec [20090605-11:35:07.191516810] [20090605-11:35:07.194436872] Total Results [20090605-11:35:07.212560279] =============== [20090605-11:35:07.215260146] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090605-11:35:07.218453837] ======= ============ ========= ======= =========== ========== [20090605-11:35:07.221505682] write : 8843520 28835.95 100.000% 100.000% 113MB/sec [20090605-11:35:07.224209808] - [20090605-11:35:07.227039672] 28835.95 Transactions per Second [20090605-11:35:07.230015518] [20090605-11:35:07.233239791] Throughput Results [20090605-11:35:07.251361434] =================== [20090605-11:35:07.254157271] Write Throughput: 113MB/sec [20090605-11:35:07.256938903] [20090605-11:35:07.259691116] System Call Latency statistics in millisecs [20090605-11:35:07.262726879] ===== [20090605-11:35:07.265581579] Min Avg Max Total Calls [20090605-11:35:07.268544954] ======== ======== ======== ============ [20090605-11:35:07.271246325] [ open] 0.012000 0.069269 100.593002 6909 [20090605-11:35:07.273949476] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:35:07.276571269] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:35:07.279226342] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:35:07.281806742] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:35:07.284403598] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:35:07.287055754] msec_range[5] 100.000000 - 200.000000 : 1 [20090605-11:35:07.289747521] msec_range[6] 50.000000 - 100.000000 : 1 [20090605-11:35:07.292612003] msec_range[7] 20.000000 - 50.000000 : 1 [20090605-11:35:07.295307574] msec_range[8] 10.000000 - 20.000000 : 2 [20090605-11:35:07.297955740] msec_range[9] 5.000000 - 10.000000 : 3 [20090605-11:35:07.300664407] msec_range[10] 2.000000 - 5.000000 : 3 [20090605-11:35:07.303212237] msec_range[11] 1.000000 - 2.000000 : 0 [20090605-11:35:07.305807886] msec_range[12] 0.500000 - 1.000000 : 0 [20090605-11:35:07.308431490] msec_range[13] 0.200000 - 0.500000 : 3 [20090605-11:35:07.311169983] msec_range[14] 0.100000 - 0.200000 : 12 [20090605-11:35:07.314033884] msec_range[15] 0.050000 - 0.100000 : 562 [20090605-11:35:07.316464765] msec_range[16] 0.020000 - 0.050000 : 5560 [20090605-11:35:07.319058424] msec_range[17] 0.010000 - 0.020000 : 761 [20090605-11:35:07.321698299] msec_range[18] 0.000000 - 0.010000 : 0 [20090605-11:35:07.324308380] [20090605-11:35:07.327013684] [ write] 0.008000 0.031745 101.846001 8843520 [20090605-11:35:07.329582093] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:35:07.332270793] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:35:07.334830752] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:35:07.337521118] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:35:07.340755611] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:35:07.343590830] msec_range[5] 100.000000 - 200.000000 : 3 [20090605-11:35:07.346361665] msec_range[6] 50.000000 - 100.000000 : 1483 [20090605-11:35:07.349055782] msec_range[7] 20.000000 - 50.000000 : 4 [20090605-11:35:07.351800318] msec_range[8] 10.000000 - 20.000000 : 0 [20090605-11:35:07.354429734] msec_range[9] 5.000000 - 10.000000 : 1 [20090605-11:35:07.357204777] msec_range[10] 2.000000 - 5.000000 : 51 [20090605-11:35:07.360159583] msec_range[11] 1.000000 - 2.000000 : 30 [20090605-11:35:07.363172418] msec_range[12] 0.500000 - 1.000000 : 110 [20090605-11:35:07.366821035] msec_range[13] 0.200000 - 0.500000 : 2153 [20090605-11:35:07.370065209] msec_range[14] 0.100000 - 0.200000 : 1854 [20090605-11:35:07.373126072] msec_range[15] 0.050000 - 0.100000 : 22398 [20090605-11:35:07.376303093] msec_range[16] 0.020000 - 0.050000 : 2029402 [20090605-11:35:07.379411320] msec_range[17] 0.010000 - 0.020000 : 6784107 [20090605-11:35:07.382247973] msec_range[18] 0.000000 - 0.010000 : 1924 [20090605-11:35:07.385081904] [20090605-11:35:07.387829105] [ lseek] 0.000000 0.001168 3.873000 8843520 [20090605-11:35:07.390530788] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:35:07.393178109] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:35:07.395790349] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:35:07.398400101] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:35:07.401017311] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:35:07.403552713] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-11:35:07.406112279] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-11:35:07.408742044] msec_range[7] 20.000000 - 50.000000 : 0 [20090605-11:35:07.411479373] msec_range[8] 10.000000 - 20.000000 : 0 [20090605-11:35:07.414550637] msec_range[9] 5.000000 - 10.000000 : 0 [20090605-11:35:07.417313972] msec_range[10] 2.000000 - 5.000000 : 1 [20090605-11:35:07.420067150] msec_range[11] 1.000000 - 2.000000 : 1 [20090605-11:35:07.422999918] msec_range[12] 0.500000 - 1.000000 : 1 [20090605-11:35:07.425923154] msec_range[13] 0.200000 - 0.500000 : 120 [20090605-11:35:07.428521322] msec_range[14] 0.100000 - 0.200000 : 29 [20090605-11:35:07.431251045] msec_range[15] 0.050000 - 0.100000 : 179 [20090605-11:35:07.433998409] msec_range[16] 0.020000 - 0.050000 : 867 [20090605-11:35:07.437447910] msec_range[17] 0.010000 - 0.020000 : 3801 [20090605-11:35:07.440659887] msec_range[18] 0.000000 - 0.010000 : 8838521 [20090605-11:35:07.443345604] [20090605-11:35:07.446245806] [ close] 0.004000 0.007188 0.080000 6909 [20090605-11:35:07.448938376] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:35:07.451604643] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:35:07.454476589] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:35:07.457572333] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:35:07.460213308] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:35:07.462902917] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-11:35:07.465627477] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-11:35:07.468436771] msec_range[7] 20.000000 - 50.000000 : 0 [20090605-11:35:07.471302000] msec_range[8] 10.000000 - 20.000000 : 0 [20090605-11:35:07.474198152] msec_range[9] 5.000000 - 10.000000 : 0 [20090605-11:35:07.476954088] msec_range[10] 2.000000 - 5.000000 : 0 [20090605-11:35:07.479480659] msec_range[11] 1.000000 - 2.000000 : 0 [20090605-11:35:07.482120001] msec_range[12] 0.500000 - 1.000000 : 0 [20090605-11:35:07.484740341] msec_range[13] 0.200000 - 0.500000 : 0 [20090605-11:35:07.487386921] msec_range[14] 0.100000 - 0.200000 : 0 [20090605-11:35:07.489906628] msec_range[15] 0.050000 - 0.100000 : 3 [20090605-11:35:07.492454701] msec_range[16] 0.020000 - 0.050000 : 10 [20090605-11:35:07.495066666] msec_range[17] 0.010000 - 0.020000 : 1223 [20090605-11:35:07.497689284] msec_range[18] 0.000000 - 0.010000 : 5673 [20090605-11:35:07.500450228] [20090605-11:35:07.503194612] [20090605-11:35:07.505920267] [20090605-11:35:07.508840238] [20090605-11:35:07.511332304] 5.1% User Time [20090605-11:35:07.513936912] 94.0% System Time [20090605-11:35:07.516587506] 99.1% CPU Utilization [20090605-11:35:07.519851759] Profilers reporting [20090605-11:35:24.384043166] Profilers postprocessing [20090605-11:35:24.647450790] Processing File : iostat.001 [20090605-11:35:24.649738062] Discovered iostat_interval=[5] [20090605-11:35:25.416853365] Processing Directory : sar.breakout.001 [20090605-11:35:25.419117304] Discovered sar_interval=[5] [20090605-11:35:25.591423012] Processing File : mpstat.001 [20090605-11:35:25.593634618] Discovered mpstat_interval=[5] [20090605-11:35:26.736978498] Stopping profiling. [20090605-11:35:26.741823071] Killing daemon. [20090605-11:35:29.004667624] Processing File : oprofile.001 [20090605-11:35:29.006969316] Processing File : oprofile-brief.001 [20090605-11:35:30.550589365] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-06-05_1047/btrfsnewformat-6-1-nodatacow' [20090605-11:35:34.625609814] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090605-11:35:38.420106472] PROCESSING COMMAND : 'mount -t btrfs -o nodatacow /dev/ffsbdev1 /mnt/ffsb1' [20090605-11:35:38.660031385] ONLY : Command [run random_writes__threads_0016 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb reuse=1 num_threads=16] found for me [20090605-11:35:38.713693348] PROCESSING COMMAND : 'run random_writes__threads_0016 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb reuse=1 num_threads=16' [20090605-11:35:38.763627381] new log requested [20090605-11:35:38.794376528] Running command ffsb [20090605-11:35:50.004654369] 06/05/2009-11:35:49 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb Succeeded [20090605-11:35:50.016185688] Importing argument : reuse=1 [20090605-11:35:50.029964346] Importing argument : num_threads=16 [20090605-11:35:50.058931095] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090605-11:35:50.146658930] FFSB version 6.0-RC2.1 started [20090605-11:35:50.149022958] [20090605-11:35:50.212073673] benchmark time = 300 [20090605-11:35:50.214276262] ThreadGroup 0 [20090605-11:35:50.216448666] ================ [20090605-11:35:50.218460527] num_threads = 16 [20090605-11:35:50.220461706] [20090605-11:35:50.222384876] read_random = off [20090605-11:35:50.224400921] read_size = 0 (0B) [20090605-11:35:50.226423822] read_blocksize = 0 (0B) [20090605-11:35:50.228738513] read_skip = off [20090605-11:35:50.231015155] read_skipsize = 0 (0B) [20090605-11:35:50.233201326] [20090605-11:35:50.235184592] write_random = on [20090605-11:35:50.237237499] write_size = 5242880 (5MB) [20090605-11:35:50.239212993] fsync_file = 0 [20090605-11:35:50.241277778] write_blocksize = 4096 (4KB) [20090605-11:35:50.243292462] wait time = 0 [20090605-11:35:50.245250049] [20090605-11:35:50.247133398] op weights [20090605-11:35:50.249116081] read = 0 (0.00%) [20090605-11:35:50.251068351] readall = 0 (0.00%) [20090605-11:35:50.252968986] write = 1 (100.00%) [20090605-11:35:50.254949396] create = 0 (0.00%) [20090605-11:35:50.256903564] append = 0 (0.00%) [20090605-11:35:50.258931240] delete = 0 (0.00%) [20090605-11:35:50.260943443] metaop = 0 (0.00%) [20090605-11:35:50.263140588] createdir = 0 (0.00%) [20090605-11:35:50.267831869] stat = 0 (0.00%) [20090605-11:35:50.270241191] writeall = 0 (0.00%) [20090605-11:35:50.272285534] writeall_fsync = 0 (0.00%) [20090605-11:35:50.274448171] open_close = 0 (0.00%) [20090605-11:35:50.276631405] write_fsync = 0 (0.00%) [20090605-11:35:50.278724737] create_fsync = 0 (0.00%) [20090605-11:35:50.280755962] append_fsync = 0 (0.00%) [20090605-11:35:50.282709213] [20090605-11:35:50.284757519] FileSystem /mnt/ffsb1 [20090605-11:35:50.286694097] ========== [20090605-11:35:50.288738119] num_dirs = 0 [20090605-11:35:50.290794047] starting files = 1024 [20090605-11:35:50.292762455] [20090605-11:35:50.294755184] min file size = 104857600 (100MB) [20090605-11:35:50.296733543] max file size = 104857600 (100MB) [20090605-11:35:50.299335137] directio = off [20090605-11:35:50.301274195] alignedio = on [20090605-11:35:50.303219853] bufferedio = off [20090605-11:35:50.305283687] [20090605-11:35:50.307293841] aging is off [20090605-11:35:50.309387065] current utilization = 4.47% [20090605-11:35:50.311551136] [20090605-11:35:50.313611768] checking existing fs: /mnt/ffsb1 [20090605-11:35:50.373592459] fs setup took 0 secs [20090605-11:35:50.848126416] Syncing()...0 sec [20090605-11:35:50.850287496] Starting Actual Benchmark At: Fri Jun 5 11:35:50 2009 [20090605-11:35:50.866103130] [20090605-11:40:59.413274147] Syncing()...6 sec [20090605-11:40:59.506480799] FFSB benchmark finished at: Fri Jun 5 11:40:59 2009 [20090605-11:40:59.509925844] [20090605-11:40:59.513350387] Results: [20090605-11:40:59.582236100] Benchmark took 308.24 sec [20090605-11:40:59.585114516] [20090605-11:40:59.588299550] Total Results [20090605-11:40:59.606200177] =============== [20090605-11:40:59.609094679] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090605-11:40:59.612132620] ======= ============ ========= ======= =========== ========== [20090605-11:40:59.615017215] write : 8352000 27095.68 100.000% 100.000% 106MB/sec [20090605-11:40:59.618007252] - [20090605-11:40:59.620704680] 27095.68 Transactions per Second [20090605-11:40:59.623341468] [20090605-11:40:59.626401657] Throughput Results [20090605-11:40:59.645535724] =================== [20090605-11:40:59.648476725] Write Throughput: 106MB/sec [20090605-11:40:59.651602349] [20090605-11:40:59.654445872] System Call Latency statistics in millisecs [20090605-11:40:59.657436894] ===== [20090605-11:40:59.660121607] Min Avg Max Total Calls [20090605-11:40:59.663075864] ======== ======== ======== ============ [20090605-11:40:59.666283246] [ open] 0.009000 0.194006 101.906998 6525 [20090605-11:40:59.669328685] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:40:59.672034029] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:40:59.674859133] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:40:59.677538821] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:40:59.680239411] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:40:59.682715742] msec_range[5] 100.000000 - 200.000000 : 2 [20090605-11:40:59.685402128] msec_range[6] 50.000000 - 100.000000 : 6 [20090605-11:40:59.687993637] msec_range[7] 20.000000 - 50.000000 : 6 [20090605-11:40:59.690859377] msec_range[8] 10.000000 - 20.000000 : 2 [20090605-11:40:59.693692712] msec_range[9] 5.000000 - 10.000000 : 4 [20090605-11:40:59.696597316] msec_range[10] 2.000000 - 5.000000 : 3 [20090605-11:40:59.699445572] msec_range[11] 1.000000 - 2.000000 : 0 [20090605-11:40:59.702364053] msec_range[12] 0.500000 - 1.000000 : 41 [20090605-11:40:59.705284946] msec_range[13] 0.200000 - 0.500000 : 105 [20090605-11:40:59.708096018] msec_range[14] 0.100000 - 0.200000 : 436 [20090605-11:40:59.710763419] msec_range[15] 0.050000 - 0.100000 : 709 [20090605-11:40:59.713748309] msec_range[16] 0.020000 - 0.050000 : 4993 [20090605-11:40:59.716500521] msec_range[17] 0.010000 - 0.020000 : 216 [20090605-11:40:59.719287959] msec_range[18] 0.000000 - 0.010000 : 2 [20090605-11:40:59.721859642] [20090605-11:40:59.724501617] [ write] 0.009000 0.564007 4939.509766 8352000 [20090605-11:40:59.727018958] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:40:59.729623571] msec_range[1] 2000.000000 - 5000.000000 : 136 [20090605-11:40:59.732174586] msec_range[2] 1000.000000 - 2000.000000 : 247 [20090605-11:40:59.734895108] msec_range[3] 500.000000 - 1000.000000 : 3635 [20090605-11:40:59.737602093] msec_range[4] 200.000000 - 500.000000 : 1153 [20090605-11:40:59.740449611] msec_range[5] 100.000000 - 200.000000 : 677 [20090605-11:40:59.743599135] msec_range[6] 50.000000 - 100.000000 : 2549 [20090605-11:40:59.746438754] msec_range[7] 20.000000 - 50.000000 : 3905 [20090605-11:40:59.749282137] msec_range[8] 10.000000 - 20.000000 : 2324 [20090605-11:40:59.752302907] msec_range[9] 5.000000 - 10.000000 : 2133 [20090605-11:40:59.755298433] msec_range[10] 2.000000 - 5.000000 : 2293 [20090605-11:40:59.757915753] msec_range[11] 1.000000 - 2.000000 : 13659 [20090605-11:40:59.760793440] msec_range[12] 0.500000 - 1.000000 : 116055 [20090605-11:40:59.763505071] msec_range[13] 0.200000 - 0.500000 : 539712 [20090605-11:40:59.766179035] msec_range[14] 0.100000 - 0.200000 : 837184 [20090605-11:40:59.768673753] msec_range[15] 0.050000 - 0.100000 : 1002942 [20090605-11:40:59.771426579] msec_range[16] 0.020000 - 0.050000 : 4226443 [20090605-11:40:59.774461173] msec_range[17] 0.010000 - 0.020000 : 1596822 [20090605-11:40:59.777163016] msec_range[18] 0.000000 - 0.010000 : 131 [20090605-11:40:59.779572081] [20090605-11:40:59.782304298] [ lseek] 0.000000 0.010989 5451.020020 8352000 [20090605-11:40:59.784953441] msec_range[0] 5000.000000 - 10000.000000 : 1 [20090605-11:40:59.787793604] msec_range[1] 2000.000000 - 5000.000000 : 5 [20090605-11:40:59.790390127] msec_range[2] 1000.000000 - 2000.000000 : 4 [20090605-11:40:59.794302444] msec_range[3] 500.000000 - 1000.000000 : 41 [20090605-11:40:59.797289706] msec_range[4] 200.000000 - 500.000000 : 29 [20090605-11:40:59.800225867] msec_range[5] 100.000000 - 200.000000 : 26 [20090605-11:40:59.803253178] msec_range[6] 50.000000 - 100.000000 : 33 [20090605-11:40:59.806496778] msec_range[7] 20.000000 - 50.000000 : 64 [20090605-11:40:59.809150097] msec_range[8] 10.000000 - 20.000000 : 59 [20090605-11:40:59.811906438] msec_range[9] 5.000000 - 10.000000 : 66 [20090605-11:40:59.814571432] msec_range[10] 2.000000 - 5.000000 : 78 [20090605-11:40:59.817277732] msec_range[11] 1.000000 - 2.000000 : 49 [20090605-11:40:59.819803095] msec_range[12] 0.500000 - 1.000000 : 414 [20090605-11:40:59.822518286] msec_range[13] 0.200000 - 0.500000 : 2497 [20090605-11:40:59.825139953] msec_range[14] 0.100000 - 0.200000 : 4969 [20090605-11:40:59.827721243] msec_range[15] 0.050000 - 0.100000 : 7924 [20090605-11:40:59.830266352] msec_range[16] 0.020000 - 0.050000 : 32448 [20090605-11:40:59.832886811] msec_range[17] 0.010000 - 0.020000 : 37938 [20090605-11:40:59.835474078] msec_range[18] 0.000000 - 0.010000 : 8265355 [20090605-11:40:59.838056300] [20090605-11:40:59.840548565] [ close] 0.003000 0.010462 2.929000 6525 [20090605-11:40:59.843198437] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:40:59.845669885] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:40:59.848309309] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:40:59.850887576] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:40:59.853468238] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:40:59.856015187] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-11:40:59.860493806] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-11:40:59.863093419] msec_range[7] 20.000000 - 50.000000 : 0 [20090605-11:40:59.865782644] msec_range[8] 10.000000 - 20.000000 : 0 [20090605-11:40:59.868572648] msec_range[9] 5.000000 - 10.000000 : 0 [20090605-11:40:59.871259375] msec_range[10] 2.000000 - 5.000000 : 1 [20090605-11:40:59.873717238] msec_range[11] 1.000000 - 2.000000 : 0 [20090605-11:40:59.876384584] msec_range[12] 0.500000 - 1.000000 : 1 [20090605-11:40:59.879122612] msec_range[13] 0.200000 - 0.500000 : 4 [20090605-11:40:59.881803172] msec_range[14] 0.100000 - 0.200000 : 1 [20090605-11:40:59.884316736] msec_range[15] 0.050000 - 0.100000 : 9 [20090605-11:40:59.886986213] msec_range[16] 0.020000 - 0.050000 : 110 [20090605-11:40:59.889507955] msec_range[17] 0.010000 - 0.020000 : 2306 [20090605-11:40:59.892123954] msec_range[18] 0.000000 - 0.010000 : 4093 [20090605-11:40:59.894550230] [20090605-11:40:59.897273695] [20090605-11:40:59.899839590] [20090605-11:40:59.902468455] [20090605-11:40:59.905016148] 7.5% User Time [20090605-11:40:59.907566996] 568.6% System Time [20090605-11:40:59.910582927] 576.2% CPU Utilization [20090605-11:40:59.913596952] Profilers reporting [20090605-11:41:11.524595367] Profilers postprocessing [20090605-11:41:11.783225903] Processing File : iostat.001 [20090605-11:41:11.785648312] Discovered iostat_interval=[5] [20090605-11:41:12.570140971] Processing Directory : sar.breakout.001 [20090605-11:41:12.572624767] Discovered sar_interval=[5] [20090605-11:41:12.749902377] Processing File : mpstat.001 [20090605-11:41:12.752216273] Discovered mpstat_interval=[5] [20090605-11:41:13.898390956] Stopping profiling. [20090605-11:41:13.905447152] Killing daemon. [20090605-11:41:16.193140019] Processing File : oprofile.001 [20090605-11:41:16.195446733] Processing File : oprofile-brief.001 [20090605-11:41:17.739705158] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-06-05_1047/btrfsnewformat-6-1-nodatacow' [20090605-11:41:28.834708168] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090605-11:41:32.625039591] PROCESSING COMMAND : 'mount -t btrfs -o nodatacow /dev/ffsbdev1 /mnt/ffsb1' [20090605-11:41:32.861764819] ONLY : Command [run random_writes__threads_0128 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb reuse=1 num_threads=128] found for me [20090605-11:41:32.914785187] PROCESSING COMMAND : 'run random_writes__threads_0128 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb reuse=1 num_threads=128' [20090605-11:41:32.964232583] new log requested [20090605-11:41:33.006758440] Running command ffsb [20090605-11:41:44.331724353] 06/05/2009-11:41:44 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb Succeeded [20090605-11:41:44.343299150] Importing argument : reuse=1 [20090605-11:41:44.356851010] Importing argument : num_threads=128 [20090605-11:41:44.386222621] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090605-11:41:44.470106769] FFSB version 6.0-RC2.1 started [20090605-11:41:44.472393822] [20090605-11:41:45.001334487] benchmark time = 300 [20090605-11:41:45.003627001] ThreadGroup 0 [20090605-11:41:45.005934364] ================ [20090605-11:41:45.008334252] num_threads = 128 [20090605-11:41:45.010560401] [20090605-11:41:45.012724617] read_random = off [20090605-11:41:45.014714873] read_size = 0 (0B) [20090605-11:41:45.016650974] read_blocksize = 0 (0B) [20090605-11:41:45.018666647] read_skip = off [20090605-11:41:45.020682001] read_skipsize = 0 (0B) [20090605-11:41:45.022637083] [20090605-11:41:45.024576545] write_random = on [20090605-11:41:45.026544396] write_size = 5242880 (5MB) [20090605-11:41:45.028564050] fsync_file = 0 [20090605-11:41:45.030492469] write_blocksize = 4096 (4KB) [20090605-11:41:45.032426513] wait time = 0 [20090605-11:41:45.034391014] [20090605-11:41:45.036399684] op weights [20090605-11:41:45.038401595] read = 0 (0.00%) [20090605-11:41:45.040549216] readall = 0 (0.00%) [20090605-11:41:45.042602859] write = 1 (100.00%) [20090605-11:41:45.044569674] create = 0 (0.00%) [20090605-11:41:45.046533826] append = 0 (0.00%) [20090605-11:41:45.048437119] delete = 0 (0.00%) [20090605-11:41:45.050396353] metaop = 0 (0.00%) [20090605-11:41:45.052343143] createdir = 0 (0.00%) [20090605-11:41:45.054284245] stat = 0 (0.00%) [20090605-11:41:45.059290344] writeall = 0 (0.00%) [20090605-11:41:45.063008997] writeall_fsync = 0 (0.00%) [20090605-11:41:45.064943711] open_close = 0 (0.00%) [20090605-11:41:45.066901760] write_fsync = 0 (0.00%) [20090605-11:41:45.068982954] create_fsync = 0 (0.00%) [20090605-11:41:45.071046145] append_fsync = 0 (0.00%) [20090605-11:41:45.072960738] [20090605-11:41:45.074901711] FileSystem /mnt/ffsb1 [20090605-11:41:45.076860590] ========== [20090605-11:41:45.078918895] num_dirs = 0 [20090605-11:41:45.080898339] starting files = 1024 [20090605-11:41:45.082933870] [20090605-11:41:45.085000889] min file size = 104857600 (100MB) [20090605-11:41:45.086978267] max file size = 104857600 (100MB) [20090605-11:41:45.088935196] directio = off [20090605-11:41:45.090859298] alignedio = on [20090605-11:41:45.092859127] bufferedio = off [20090605-11:41:45.094839102] [20090605-11:41:45.096954919] aging is off [20090605-11:41:45.099001610] current utilization = 4.47% [20090605-11:41:45.101063608] [20090605-11:41:45.103134945] checking existing fs: /mnt/ffsb1 [20090605-11:41:45.167253756] fs setup took 0 secs [20090605-11:41:45.621497225] Syncing()...0 sec [20090605-11:41:45.626303577] Starting Actual Benchmark At: Fri Jun 5 11:41:45 2009 [20090605-11:41:45.641623573] [20090605-11:46:56.346552542] Syncing()...4 sec [20090605-11:46:56.400611521] FFSB benchmark finished at: Fri Jun 5 11:46:55 2009 [20090605-11:46:56.403921668] [20090605-11:46:56.407197053] Results: [20090605-11:46:56.456814687] Benchmark took 310.26 sec [20090605-11:46:56.459545828] [20090605-11:46:56.462515027] Total Results [20090605-11:46:56.480814132] =============== [20090605-11:46:56.483639879] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090605-11:46:56.486568849] ======= ============ ========= ======= =========== ========== [20090605-11:46:56.489490383] write : 6886400 22195.30 100.000% 100.000% 86.7MB/sec [20090605-11:46:56.492636940] - [20090605-11:46:56.495569078] 22195.30 Transactions per Second [20090605-11:46:56.498606227] [20090605-11:46:56.501343983] Throughput Results [20090605-11:46:56.519266169] =================== [20090605-11:46:56.521876900] Write Throughput: 86.7MB/sec [20090605-11:46:56.524733765] [20090605-11:46:56.527448113] System Call Latency statistics in millisecs [20090605-11:46:56.530220989] ===== [20090605-11:46:56.533165543] Min Avg Max Total Calls [20090605-11:46:56.535841584] ======== ======== ======== ============ [20090605-11:46:56.538611999] [ open] 0.007000 24.744835 6268.542969 5380 [20090605-11:46:56.541187991] msec_range[0] 5000.000000 - 10000.000000 : 5 [20090605-11:46:56.543887183] msec_range[1] 2000.000000 - 5000.000000 : 22 [20090605-11:46:56.546542602] msec_range[2] 1000.000000 - 2000.000000 : 15 [20090605-11:46:56.549267478] msec_range[3] 500.000000 - 1000.000000 : 13 [20090605-11:46:56.551864650] msec_range[4] 200.000000 - 500.000000 : 1 [20090605-11:46:56.554501277] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-11:46:56.557003400] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-11:46:56.559868685] msec_range[7] 20.000000 - 50.000000 : 1 [20090605-11:46:56.562524101] msec_range[8] 10.000000 - 20.000000 : 1 [20090605-11:46:56.565354092] msec_range[9] 5.000000 - 10.000000 : 0 [20090605-11:46:56.568133234] msec_range[10] 2.000000 - 5.000000 : 1 [20090605-11:46:56.570861187] msec_range[11] 1.000000 - 2.000000 : 2 [20090605-11:46:56.573566165] msec_range[12] 0.500000 - 1.000000 : 30 [20090605-11:46:56.576145674] msec_range[13] 0.200000 - 0.500000 : 64 [20090605-11:46:56.578887365] msec_range[14] 0.100000 - 0.200000 : 170 [20090605-11:46:56.581633266] msec_range[15] 0.050000 - 0.100000 : 826 [20090605-11:46:56.584357341] msec_range[16] 0.020000 - 0.050000 : 4024 [20090605-11:46:56.587097388] msec_range[17] 0.010000 - 0.020000 : 187 [20090605-11:46:56.589911870] msec_range[18] 0.000000 - 0.010000 : 18 [20090605-11:46:56.592552846] [20090605-11:46:56.595149237] [ write] 0.009000 4.877872 16612.054688 6886400 [20090605-11:46:56.598249221] msec_range[0] 5000.000000 - 10000.000000 : 2436 [20090605-11:46:56.600913722] msec_range[1] 2000.000000 - 5000.000000 : 3086 [20090605-11:46:56.603625672] msec_range[2] 1000.000000 - 2000.000000 : 1752 [20090605-11:46:56.606272203] msec_range[3] 500.000000 - 1000.000000 : 2446 [20090605-11:46:56.608859094] msec_range[4] 200.000000 - 500.000000 : 3558 [20090605-11:46:56.611517073] msec_range[5] 100.000000 - 200.000000 : 2120 [20090605-11:46:56.614279892] msec_range[6] 50.000000 - 100.000000 : 1612 [20090605-11:46:56.616987246] msec_range[7] 20.000000 - 50.000000 : 2102 [20090605-11:46:56.619562189] msec_range[8] 10.000000 - 20.000000 : 1411 [20090605-11:46:56.622264246] msec_range[9] 5.000000 - 10.000000 : 1313 [20090605-11:46:56.625304828] msec_range[10] 2.000000 - 5.000000 : 2170 [20090605-11:46:56.628381245] msec_range[11] 1.000000 - 2.000000 : 11035 [20090605-11:46:56.630965006] msec_range[12] 0.500000 - 1.000000 : 70100 [20090605-11:46:56.633646642] msec_range[13] 0.200000 - 0.500000 : 273867 [20090605-11:46:56.636304054] msec_range[14] 0.100000 - 0.200000 : 371361 [20090605-11:46:56.638845175] msec_range[15] 0.050000 - 0.100000 : 577232 [20090605-11:46:56.641590350] msec_range[16] 0.020000 - 0.050000 : 3617277 [20090605-11:46:56.644402141] msec_range[17] 0.010000 - 0.020000 : 1941400 [20090605-11:46:56.647169346] msec_range[18] 0.000000 - 0.010000 : 95 [20090605-11:46:56.649743502] [20090605-11:46:56.653769798] [ lseek] 0.000000 0.751136 25413.980469 6886400 [20090605-11:46:56.659111334] msec_range[0] 5000.000000 - 10000.000000 : 390 [20090605-11:46:56.661922528] msec_range[1] 2000.000000 - 5000.000000 : 416 [20090605-11:46:56.664858212] msec_range[2] 1000.000000 - 2000.000000 : 258 [20090605-11:46:56.667711800] msec_range[3] 500.000000 - 1000.000000 : 272 [20090605-11:46:56.670672115] msec_range[4] 200.000000 - 500.000000 : 283 [20090605-11:46:56.673397905] msec_range[5] 100.000000 - 200.000000 : 159 [20090605-11:46:56.676183190] msec_range[6] 50.000000 - 100.000000 : 109 [20090605-11:46:56.678744536] msec_range[7] 20.000000 - 50.000000 : 162 [20090605-11:46:56.681355372] msec_range[8] 10.000000 - 20.000000 : 96 [20090605-11:46:56.683922249] msec_range[9] 5.000000 - 10.000000 : 91 [20090605-11:46:56.686609885] msec_range[10] 2.000000 - 5.000000 : 130 [20090605-11:46:56.689489517] msec_range[11] 1.000000 - 2.000000 : 278 [20090605-11:46:56.692205946] msec_range[12] 0.500000 - 1.000000 : 1385 [20090605-11:46:56.694953752] msec_range[13] 0.200000 - 0.500000 : 9174 [20090605-11:46:56.697800929] msec_range[14] 0.100000 - 0.200000 : 14827 [20090605-11:46:56.700507325] msec_range[15] 0.050000 - 0.100000 : 32943 [20090605-11:46:56.703146721] msec_range[16] 0.020000 - 0.050000 : 196609 [20090605-11:46:56.705744733] msec_range[17] 0.010000 - 0.020000 : 60687 [20090605-11:46:56.708403392] msec_range[18] 0.000000 - 0.010000 : 6568104 [20090605-11:46:56.711047694] [20090605-11:46:56.713653511] [ close] 0.003000 0.009883 1.095000 5380 [20090605-11:46:56.716223289] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:46:56.719269826] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:46:56.722340535] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:46:56.725026128] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:46:56.727741774] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:46:56.730704378] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-11:46:56.733453487] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-11:46:56.736025006] msec_range[7] 20.000000 - 50.000000 : 0 [20090605-11:46:56.738649993] msec_range[8] 10.000000 - 20.000000 : 0 [20090605-11:46:56.741550494] msec_range[9] 5.000000 - 10.000000 : 0 [20090605-11:46:56.744617148] msec_range[10] 2.000000 - 5.000000 : 0 [20090605-11:46:56.748026473] msec_range[11] 1.000000 - 2.000000 : 1 [20090605-11:46:56.750951336] msec_range[12] 0.500000 - 1.000000 : 3 [20090605-11:46:56.753974308] msec_range[13] 0.200000 - 0.500000 : 2 [20090605-11:46:56.757286616] msec_range[14] 0.100000 - 0.200000 : 1 [20090605-11:46:56.760071918] msec_range[15] 0.050000 - 0.100000 : 4 [20090605-11:46:56.762921667] msec_range[16] 0.020000 - 0.050000 : 65 [20090605-11:46:56.765698244] msec_range[17] 0.010000 - 0.020000 : 1708 [20090605-11:46:56.768401268] msec_range[18] 0.000000 - 0.010000 : 3596 [20090605-11:46:56.771004202] [20090605-11:46:56.773623692] [20090605-11:46:56.776313126] [20090605-11:46:56.778838076] [20090605-11:46:56.781433765] 5.6% User Time [20090605-11:46:56.784168499] 336.6% System Time [20090605-11:46:56.786877467] 342.2% CPU Utilization [20090605-11:46:56.789565649] Profilers reporting [20090605-11:47:12.671581518] Profilers postprocessing [20090605-11:47:12.929373259] Processing File : iostat.001 [20090605-11:47:12.931716551] Discovered iostat_interval=[5] [20090605-11:47:13.716190915] Processing Directory : sar.breakout.001 [20090605-11:47:13.718684015] Discovered sar_interval=[5] [20090605-11:47:13.899385537] Processing File : mpstat.001 [20090605-11:47:13.901755131] Discovered mpstat_interval=[5] [20090605-11:47:15.046446225] Stopping profiling. [20090605-11:47:15.051569264] Killing daemon. [20090605-11:47:17.339251999] Processing File : oprofile.001 [20090605-11:47:17.341441461] Processing File : oprofile-brief.001 [20090605-11:47:18.891821665] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-06-05_1047/btrfsnewformat-6-1-nodatacow' [20090605-11:47:22.953499105] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090605-11:47:26.773373956] PROCESSING COMMAND : 'mount -t btrfs -o nodatacow /dev/ffsbdev1 /mnt/ffsb1' [20090605-11:47:26.995695149] ONLY : Command [run random_writes_odirect__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb reuse=1 num_threads=1] found for me [20090605-11:47:27.050628913] PROCESSING COMMAND : 'run random_writes_odirect__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb reuse=1 num_threads=1' [20090605-11:47:27.099386421] new log requested [20090605-11:47:27.130154379] Running command ffsb [20090605-11:47:38.322602760] 06/05/2009-11:47:38 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb Succeeded [20090605-11:47:38.333554317] Importing argument : reuse=1 [20090605-11:47:38.347006504] Importing argument : num_threads=1 [20090605-11:47:38.375884673] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090605-11:47:38.462663019] FFSB version 6.0-RC2.1 started [20090605-11:47:38.465005728] [20090605-11:47:38.467218623] benchmark time = 300 [20090605-11:47:38.469565301] ThreadGroup 0 [20090605-11:47:38.471725342] ================ [20090605-11:47:38.473935476] num_threads = 1 [20090605-11:47:38.476368908] [20090605-11:47:38.478372426] read_random = off [20090605-11:47:38.480409922] read_size = 0 (0B) [20090605-11:47:38.482383731] read_blocksize = 0 (0B) [20090605-11:47:38.484646543] read_skip = off [20090605-11:47:38.486585867] read_skipsize = 0 (0B) [20090605-11:47:38.488565575] [20090605-11:47:38.490690854] write_random = on [20090605-11:47:38.492719994] write_size = 5242880 (5MB) [20090605-11:47:38.494670405] fsync_file = 0 [20090605-11:47:38.496802158] write_blocksize = 4096 (4KB) [20090605-11:47:38.498773552] wait time = 0 [20090605-11:47:38.500782829] [20090605-11:47:38.502714848] op weights [20090605-11:47:38.504730624] read = 0 (0.00%) [20090605-11:47:38.506709256] readall = 0 (0.00%) [20090605-11:47:38.508709652] write = 1 (100.00%) [20090605-11:47:38.510596085] create = 0 (0.00%) [20090605-11:47:38.512595336] append = 0 (0.00%) [20090605-11:47:38.514621010] delete = 0 (0.00%) [20090605-11:47:38.516746417] metaop = 0 (0.00%) [20090605-11:47:38.518754650] createdir = 0 (0.00%) [20090605-11:47:38.520695072] stat = 0 (0.00%) [20090605-11:47:38.522738924] writeall = 0 (0.00%) [20090605-11:47:38.524756501] writeall_fsync = 0 (0.00%) [20090605-11:47:38.526803445] open_close = 0 (0.00%) [20090605-11:47:38.528923417] write_fsync = 0 (0.00%) [20090605-11:47:38.530866157] create_fsync = 0 (0.00%) [20090605-11:47:38.532846555] append_fsync = 0 (0.00%) [20090605-11:47:38.534783481] [20090605-11:47:38.536821040] FileSystem /mnt/ffsb1 [20090605-11:47:38.539069691] ========== [20090605-11:47:38.541209393] num_dirs = 0 [20090605-11:47:38.543139992] starting files = 1024 [20090605-11:47:38.545153717] [20090605-11:47:38.547194886] min file size = 104857600 (100MB) [20090605-11:47:38.549188045] max file size = 104857600 (100MB) [20090605-11:47:38.551132090] directio = on [20090605-11:47:38.553223654] alignedio = on [20090605-11:47:38.555315314] bufferedio = off [20090605-11:47:38.557196225] [20090605-11:47:38.559383729] aging is off [20090605-11:47:38.561455452] current utilization = 4.47% [20090605-11:47:38.563533159] [20090605-11:47:38.565523035] checking existing fs: /mnt/ffsb1 [20090605-11:47:38.625634011] fs setup took 0 secs [20090605-11:47:39.045183543] Syncing()...0 sec [20090605-11:47:39.047370866] Starting Actual Benchmark At: Fri Jun 5 11:47:39 2009 [20090605-11:47:39.072726691] [20090605-11:52:40.411763193] Syncing()...0 sec [20090605-11:52:40.415209822] FFSB benchmark finished at: Fri Jun 5 11:52:40 2009 [20090605-11:52:40.418576411] [20090605-11:52:40.421591428] Results: [20090605-11:52:40.439669520] Benchmark took 301.36 sec [20090605-11:52:40.442590312] [20090605-11:52:40.445607409] Total Results [20090605-11:52:40.463344373] =============== [20090605-11:52:40.466269486] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090605-11:52:40.469409912] ======= ============ ========= ======= =========== ========== [20090605-11:52:40.472587740] write : 796160 2641.86 100.000% 100.000% 10.3MB/sec [20090605-11:52:40.475481608] - [20090605-11:52:40.478505138] 2641.86 Transactions per Second [20090605-11:52:40.481442563] [20090605-11:52:40.484294037] Throughput Results [20090605-11:52:40.505413644] =================== [20090605-11:52:40.508383791] Write Throughput: 10.3MB/sec [20090605-11:52:40.511330997] [20090605-11:52:40.515252253] System Call Latency statistics in millisecs [20090605-11:52:40.518241095] ===== [20090605-11:52:40.520952847] Min Avg Max Total Calls [20090605-11:52:40.523749487] ======== ======== ======== ============ [20090605-11:52:40.526792685] [ open] 0.011000 0.016023 0.031000 622 [20090605-11:52:40.529828769] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:52:40.533194512] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:52:40.536574554] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:52:40.539942085] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:52:40.543179929] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:52:40.546218472] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-11:52:40.549202570] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-11:52:40.551760142] msec_range[7] 20.000000 - 50.000000 : 0 [20090605-11:52:40.554884752] msec_range[8] 10.000000 - 20.000000 : 0 [20090605-11:52:40.557941487] msec_range[9] 5.000000 - 10.000000 : 0 [20090605-11:52:40.561067485] msec_range[10] 2.000000 - 5.000000 : 0 [20090605-11:52:40.564174786] msec_range[11] 1.000000 - 2.000000 : 0 [20090605-11:52:40.567734555] msec_range[12] 0.500000 - 1.000000 : 0 [20090605-11:52:40.570692834] msec_range[13] 0.200000 - 0.500000 : 0 [20090605-11:52:40.573737135] msec_range[14] 0.100000 - 0.200000 : 0 [20090605-11:52:40.577177794] msec_range[15] 0.050000 - 0.100000 : 0 [20090605-11:52:40.580236693] msec_range[16] 0.020000 - 0.050000 : 80 [20090605-11:52:40.583438222] msec_range[17] 0.010000 - 0.020000 : 542 [20090605-11:52:40.587609130] msec_range[18] 0.000000 - 0.010000 : 0 [20090605-11:52:40.590803194] [20090605-11:52:40.593590113] [ write] 0.248000 0.375170 381.837006 796160 [20090605-11:52:40.596571458] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:52:40.600575407] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:52:40.603638296] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:52:40.606765373] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:52:40.609524702] msec_range[4] 200.000000 - 500.000000 : 3 [20090605-11:52:40.612810897] msec_range[5] 100.000000 - 200.000000 : 237 [20090605-11:52:40.615900708] msec_range[6] 50.000000 - 100.000000 : 313 [20090605-11:52:40.618856910] msec_range[7] 20.000000 - 50.000000 : 249 [20090605-11:52:40.621770453] msec_range[8] 10.000000 - 20.000000 : 168 [20090605-11:52:40.624627452] msec_range[9] 5.000000 - 10.000000 : 86 [20090605-11:52:40.627602663] msec_range[10] 2.000000 - 5.000000 : 126 [20090605-11:52:40.630482227] msec_range[11] 1.000000 - 2.000000 : 2780 [20090605-11:52:40.635221933] msec_range[12] 0.500000 - 1.000000 : 1771 [20090605-11:52:40.638079292] msec_range[13] 0.200000 - 0.500000 : 790427 [20090605-11:52:40.642548755] msec_range[14] 0.100000 - 0.200000 : 0 [20090605-11:52:40.646078616] msec_range[15] 0.050000 - 0.100000 : 0 [20090605-11:52:40.648967585] msec_range[16] 0.020000 - 0.050000 : 0 [20090605-11:52:40.651784042] msec_range[17] 0.010000 - 0.020000 : 0 [20090605-11:52:40.654897795] msec_range[18] 0.000000 - 0.010000 : 0 [20090605-11:52:40.658940852] [20090605-11:52:40.662215714] [ lseek] 0.000000 0.001525 0.598000 796160 [20090605-11:52:40.665178432] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:52:40.669262842] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:52:40.672520037] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:52:40.675663057] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:52:40.679806571] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:52:40.684027624] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-11:52:40.687301648] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-11:52:40.690416139] msec_range[7] 20.000000 - 50.000000 : 0 [20090605-11:52:40.694871393] msec_range[8] 10.000000 - 20.000000 : 0 [20090605-11:52:40.698158679] msec_range[9] 5.000000 - 10.000000 : 0 [20090605-11:52:40.701118991] msec_range[10] 2.000000 - 5.000000 : 0 [20090605-11:52:40.704634969] msec_range[11] 1.000000 - 2.000000 : 0 [20090605-11:52:40.707519400] msec_range[12] 0.500000 - 1.000000 : 1 [20090605-11:52:40.710526780] msec_range[13] 0.200000 - 0.500000 : 3 [20090605-11:52:40.713481525] msec_range[14] 0.100000 - 0.200000 : 9 [20090605-11:52:40.717288880] msec_range[15] 0.050000 - 0.100000 : 2 [20090605-11:52:40.720556525] msec_range[16] 0.020000 - 0.050000 : 27 [20090605-11:52:40.723534227] msec_range[17] 0.010000 - 0.020000 : 733 [20090605-11:52:40.726704582] msec_range[18] 0.000000 - 0.010000 : 795385 [20090605-11:52:40.729557134] [20090605-11:52:40.732313315] [ close] 0.003000 0.005019 0.012000 622 [20090605-11:52:40.735352799] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:52:40.738013425] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:52:40.741180760] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:52:40.744142106] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:52:40.747067601] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:52:40.749875262] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-11:52:40.752704445] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-11:52:40.755586003] msec_range[7] 20.000000 - 50.000000 : 0 [20090605-11:52:40.758382077] msec_range[8] 10.000000 - 20.000000 : 0 [20090605-11:52:40.761327520] msec_range[9] 5.000000 - 10.000000 : 0 [20090605-11:52:40.764039973] msec_range[10] 2.000000 - 5.000000 : 0 [20090605-11:52:40.766488310] msec_range[11] 1.000000 - 2.000000 : 0 [20090605-11:52:40.769546721] msec_range[12] 0.500000 - 1.000000 : 0 [20090605-11:52:40.772449475] msec_range[13] 0.200000 - 0.500000 : 0 [20090605-11:52:40.775192492] msec_range[14] 0.100000 - 0.200000 : 0 [20090605-11:52:40.777786089] msec_range[15] 0.050000 - 0.100000 : 0 [20090605-11:52:40.780255038] msec_range[16] 0.020000 - 0.050000 : 0 [20090605-11:52:40.782513424] msec_range[17] 0.010000 - 0.020000 : 21 [20090605-11:52:40.785191113] msec_range[18] 0.000000 - 0.010000 : 601 [20090605-11:52:40.788082692] [20090605-11:52:40.790877795] [20090605-11:52:40.793575865] [20090605-11:52:40.796094771] [20090605-11:52:40.798578546] 0.7% User Time [20090605-11:52:40.800802072] 19.9% System Time [20090605-11:52:40.803520485] 20.6% CPU Utilization [20090605-11:52:40.805925006] Profilers reporting [20090605-11:52:40.808156623] /autobench/scripts/doprofilers: line 2: 8747 Terminated ${CMDS[$i]} [20090605-11:52:40.810890721] /autobench/scripts/doprofilers: line 2: 8800 Terminated ${CMDS[$i]} [20090605-11:52:52.848996359] Profilers postprocessing [20090605-11:52:52.971905630] Processing File : iostat.001 [20090605-11:52:52.974329694] Discovered iostat_interval=[5] [20090605-11:52:53.678681571] Processing Directory : sar.breakout.001 [20090605-11:52:53.681170646] Discovered sar_interval=[5] [20090605-11:52:53.851731488] Processing File : mpstat.001 [20090605-11:52:53.854196944] Discovered mpstat_interval=[5] [20090605-11:52:54.999692060] Stopping profiling. [20090605-11:52:55.005199360] Killing daemon. [20090605-11:52:56.201399457] Processing File : oprofile.001 [20090605-11:52:56.203749594] Processing File : oprofile-brief.001 [20090605-11:52:57.036966914] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-06-05_1047/btrfsnewformat-6-1-nodatacow' [20090605-11:52:59.753207977] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090605-11:52:59.895814769] PROCESSING COMMAND : 'mount -t btrfs -o nodatacow /dev/ffsbdev1 /mnt/ffsb1' [20090605-11:53:00.123063897] ONLY : Command [run random_writes_odirect__threads_0016 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb reuse=1 num_threads=16] found for me [20090605-11:53:00.176516063] PROCESSING COMMAND : 'run random_writes_odirect__threads_0016 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb reuse=1 num_threads=16' [20090605-11:53:00.225382037] new log requested [20090605-11:53:00.256422366] Running command ffsb [20090605-11:53:10.245910755] 06/05/2009-11:53:10 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb Succeeded [20090605-11:53:10.257143751] Importing argument : reuse=1 [20090605-11:53:10.270354092] Importing argument : num_threads=16 [20090605-11:53:10.298234164] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090605-11:53:10.373813038] FFSB version 6.0-RC2.1 started [20090605-11:53:10.376135278] [20090605-11:53:10.440381887] benchmark time = 300 [20090605-11:53:10.442254433] ThreadGroup 0 [20090605-11:53:10.444182478] ================ [20090605-11:53:10.446451243] num_threads = 16 [20090605-11:53:10.448459878] [20090605-11:53:10.450455647] read_random = off [20090605-11:53:10.452529371] read_size = 0 (0B) [20090605-11:53:10.454675020] read_blocksize = 0 (0B) [20090605-11:53:10.456572326] read_skip = off [20090605-11:53:10.458525713] read_skipsize = 0 (0B) [20090605-11:53:10.460483618] [20090605-11:53:10.462503679] write_random = on [20090605-11:53:10.464440081] write_size = 5242880 (5MB) [20090605-11:53:10.466346333] fsync_file = 0 [20090605-11:53:10.468365540] write_blocksize = 4096 (4KB) [20090605-11:53:10.470401776] wait time = 0 [20090605-11:53:10.472304047] [20090605-11:53:10.474543718] op weights [20090605-11:53:10.476715793] read = 0 (0.00%) [20090605-11:53:10.478620469] readall = 0 (0.00%) [20090605-11:53:10.480616315] write = 1 (100.00%) [20090605-11:53:10.482618544] create = 0 (0.00%) [20090605-11:53:10.484657253] append = 0 (0.00%) [20090605-11:53:10.486536341] delete = 0 (0.00%) [20090605-11:53:10.488473632] metaop = 0 (0.00%) [20090605-11:53:10.490495486] createdir = 0 (0.00%) [20090605-11:53:10.492498392] stat = 0 (0.00%) [20090605-11:53:10.494540879] writeall = 0 (0.00%) [20090605-11:53:10.496501777] writeall_fsync = 0 (0.00%) [20090605-11:53:10.498376718] open_close = 0 (0.00%) [20090605-11:53:10.500355685] write_fsync = 0 (0.00%) [20090605-11:53:10.502354111] create_fsync = 0 (0.00%) [20090605-11:53:10.504231668] append_fsync = 0 (0.00%) [20090605-11:53:10.506205382] [20090605-11:53:10.508168596] FileSystem /mnt/ffsb1 [20090605-11:53:10.510049104] ========== [20090605-11:53:10.512004136] num_dirs = 0 [20090605-11:53:10.513944368] starting files = 1024 [20090605-11:53:10.515807164] [20090605-11:53:10.517781218] min file size = 104857600 (100MB) [20090605-11:53:10.519793402] max file size = 104857600 (100MB) [20090605-11:53:10.522064509] directio = on [20090605-11:53:10.524470081] alignedio = on [20090605-11:53:10.526571570] bufferedio = off [20090605-11:53:10.528693720] [20090605-11:53:10.530766087] aging is off [20090605-11:53:10.532786079] current utilization = 4.47% [20090605-11:53:10.534894566] [20090605-11:53:10.537007517] checking existing fs: /mnt/ffsb1 [20090605-11:53:10.663629707] fs setup took 0 secs [20090605-11:53:11.712098257] Syncing()...1 sec [20090605-11:53:11.714664069] Starting Actual Benchmark At: Fri Jun 5 11:53:11 2009 [20090605-11:53:11.731878092] [20090605-11:58:14.195859806] Syncing()...0 sec [20090605-11:58:14.199441648] FFSB benchmark finished at: Fri Jun 5 11:58:14 2009 [20090605-11:58:14.202983817] [20090605-11:58:14.206238692] Results: [20090605-11:58:14.224538442] Benchmark took 302.48 sec [20090605-11:58:14.227476122] [20090605-11:58:14.230470329] Total Results [20090605-11:58:14.248739491] =============== [20090605-11:58:14.252274121] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090605-11:58:14.255256427] ======= ============ ========= ======= =========== ========== [20090605-11:58:14.258352416] write : 4111360 13592.13 100.000% 100.000% 53.1MB/sec [20090605-11:58:14.261411298] - [20090605-11:58:14.264433091] 13592.13 Transactions per Second [20090605-11:58:14.267305448] [20090605-11:58:14.270288066] Throughput Results [20090605-11:58:14.291350949] =================== [20090605-11:58:14.294495131] Write Throughput: 53.1MB/sec [20090605-11:58:14.297910328] [20090605-11:58:14.300888695] System Call Latency statistics in millisecs [20090605-11:58:14.303769900] ===== [20090605-11:58:14.306734362] Min Avg Max Total Calls [20090605-11:58:14.309998295] ======== ======== ======== ============ [20090605-11:58:14.314226061] [ open] 0.008000 0.024823 0.701000 3212 [20090605-11:58:14.317816008] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:58:14.321029031] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:58:14.324079624] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:58:14.327264720] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:58:14.330034344] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:58:14.332754611] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-11:58:14.335366187] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-11:58:14.337870634] msec_range[7] 20.000000 - 50.000000 : 0 [20090605-11:58:14.340884694] msec_range[8] 10.000000 - 20.000000 : 0 [20090605-11:58:14.343862589] msec_range[9] 5.000000 - 10.000000 : 0 [20090605-11:58:14.346712117] msec_range[10] 2.000000 - 5.000000 : 0 [20090605-11:58:14.350941586] msec_range[11] 1.000000 - 2.000000 : 0 [20090605-11:58:14.354994794] msec_range[12] 0.500000 - 1.000000 : 1 [20090605-11:58:14.358253036] msec_range[13] 0.200000 - 0.500000 : 1 [20090605-11:58:14.361347138] msec_range[14] 0.100000 - 0.200000 : 2 [20090605-11:58:14.364302045] msec_range[15] 0.050000 - 0.100000 : 35 [20090605-11:58:14.367542495] msec_range[16] 0.020000 - 0.050000 : 2527 [20090605-11:58:14.370419445] msec_range[17] 0.010000 - 0.020000 : 619 [20090605-11:58:14.374383171] msec_range[18] 0.000000 - 0.010000 : 27 [20090605-11:58:14.377559373] [20090605-11:58:14.380860752] [ write] 0.252000 1.170069 362.734009 4111360 [20090605-11:58:14.383592248] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:58:14.386718061] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:58:14.389595472] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:58:14.392576269] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:58:14.395795032] msec_range[4] 200.000000 - 500.000000 : 450 [20090605-11:58:14.399720353] msec_range[5] 100.000000 - 200.000000 : 6572 [20090605-11:58:14.402559886] msec_range[6] 50.000000 - 100.000000 : 11785 [20090605-11:58:14.406332834] msec_range[7] 20.000000 - 50.000000 : 13769 [20090605-11:58:14.409192847] msec_range[8] 10.000000 - 20.000000 : 6904 [20090605-11:58:14.412058639] msec_range[9] 5.000000 - 10.000000 : 4042 [20090605-11:58:14.415222944] msec_range[10] 2.000000 - 5.000000 : 5262 [20090605-11:58:14.418084104] msec_range[11] 1.000000 - 2.000000 : 198912 [20090605-11:58:14.420933764] msec_range[12] 0.500000 - 1.000000 : 2686727 [20090605-11:58:14.424112460] msec_range[13] 0.200000 - 0.500000 : 1176937 [20090605-11:58:14.427345577] msec_range[14] 0.100000 - 0.200000 : 0 [20090605-11:58:14.430568512] msec_range[15] 0.050000 - 0.100000 : 0 [20090605-11:58:14.433672468] msec_range[16] 0.020000 - 0.050000 : 0 [20090605-11:58:14.436853074] msec_range[17] 0.010000 - 0.020000 : 0 [20090605-11:58:14.439877406] msec_range[18] 0.000000 - 0.010000 : 0 [20090605-11:58:14.442852640] [20090605-11:58:14.445978669] [ lseek] 0.000000 0.002065 3.846000 4111360 [20090605-11:58:14.449183815] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:58:14.452430329] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:58:14.455455881] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:58:14.458614594] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:58:14.465010932] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:58:14.468484194] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-11:58:14.471514189] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-11:58:14.475225417] msec_range[7] 20.000000 - 50.000000 : 0 [20090605-11:58:14.478555146] msec_range[8] 10.000000 - 20.000000 : 0 [20090605-11:58:14.482430003] msec_range[9] 5.000000 - 10.000000 : 0 [20090605-11:58:14.487679155] msec_range[10] 2.000000 - 5.000000 : 2 [20090605-11:58:14.490827873] msec_range[11] 1.000000 - 2.000000 : 12 [20090605-11:58:14.494106793] msec_range[12] 0.500000 - 1.000000 : 51 [20090605-11:58:14.497876641] msec_range[13] 0.200000 - 0.500000 : 141 [20090605-11:58:14.500762556] msec_range[14] 0.100000 - 0.200000 : 528 [20090605-11:58:14.503716979] msec_range[15] 0.050000 - 0.100000 : 2398 [20090605-11:58:14.506844889] msec_range[16] 0.020000 - 0.050000 : 5540 [20090605-11:58:14.510266740] msec_range[17] 0.010000 - 0.020000 : 13269 [20090605-11:58:14.513284394] msec_range[18] 0.000000 - 0.010000 : 4089419 [20090605-11:58:14.516008619] [20090605-11:58:14.518919094] [ close] 0.003000 0.008325 0.791000 3212 [20090605-11:58:14.521919313] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-11:58:14.524819856] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-11:58:14.527851604] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-11:58:14.530863747] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-11:58:14.533856167] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-11:58:14.536719052] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-11:58:14.539660980] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-11:58:14.542685375] msec_range[7] 20.000000 - 50.000000 : 0 [20090605-11:58:14.545756421] msec_range[8] 10.000000 - 20.000000 : 0 [20090605-11:58:14.548489423] msec_range[9] 5.000000 - 10.000000 : 0 [20090605-11:58:14.551450053] msec_range[10] 2.000000 - 5.000000 : 0 [20090605-11:58:14.554424939] msec_range[11] 1.000000 - 2.000000 : 0 [20090605-11:58:14.557099812] msec_range[12] 0.500000 - 1.000000 : 2 [20090605-11:58:14.559675677] msec_range[13] 0.200000 - 0.500000 : 1 [20090605-11:58:14.562369677] msec_range[14] 0.100000 - 0.200000 : 0 [20090605-11:58:14.565240673] msec_range[15] 0.050000 - 0.100000 : 0 [20090605-11:58:14.567971238] msec_range[16] 0.020000 - 0.050000 : 19 [20090605-11:58:14.570827555] msec_range[17] 0.010000 - 0.020000 : 650 [20090605-11:58:14.573550500] msec_range[18] 0.000000 - 0.010000 : 2540 [20090605-11:58:14.576291136] [20090605-11:58:14.578887784] [20090605-11:58:14.581609260] [20090605-11:58:14.584283332] [20090605-11:58:14.586882962] 4.6% User Time [20090605-11:58:14.589544348] 164.4% System Time [20090605-11:58:14.592228393] 169.0% CPU Utilization [20090605-11:58:14.594796182] Profilers reporting [20090605-11:58:14.597494820] /autobench/scripts/doprofilers: line 2: 15388 Terminated ${CMDS[$i]} [20090605-11:58:14.600174515] /autobench/scripts/doprofilers: line 2: 15409 Terminated ${CMDS[$i]} [20090605-11:58:14.602733009] /autobench/scripts/doprofilers: line 2: 15444 Terminated ${CMDS[$i]} [20090605-11:58:26.676070176] Profilers postprocessing [20090605-11:58:26.794945790] Processing File : iostat.001 [20090605-11:58:26.797302808] Discovered iostat_interval=[5] [20090605-11:58:27.523941227] Processing Directory : sar.breakout.001 [20090605-11:58:27.526443675] Discovered sar_interval=[5] [20090605-11:58:27.695516764] Processing File : mpstat.001 [20090605-11:58:27.697986421] Discovered mpstat_interval=[5] [20090605-11:58:28.843723978] Stopping profiling. [20090605-11:58:28.850678550] Killing daemon. [20090605-11:58:30.043287533] Processing File : oprofile.001 [20090605-11:58:30.045775961] Processing File : oprofile-brief.001 [20090605-11:58:30.871870760] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-06-05_1047/btrfsnewformat-6-1-nodatacow' [20090605-11:58:33.664988324] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090605-11:58:33.811848390] PROCESSING COMMAND : 'mount -t btrfs -o nodatacow /dev/ffsbdev1 /mnt/ffsb1' [20090605-11:58:34.044306018] ONLY : Command [run random_writes_odirect__threads_0128 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb reuse=1 num_threads=128] found for me [20090605-11:58:34.098062974] PROCESSING COMMAND : 'run random_writes_odirect__threads_0128 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb reuse=1 num_threads=128' [20090605-11:58:34.147680641] new log requested [20090605-11:58:34.176245266] Running command ffsb [20090605-11:58:44.193622902] 06/05/2009-11:58:44 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb Succeeded [20090605-11:58:44.204840422] Importing argument : reuse=1 [20090605-11:58:44.218282212] Importing argument : num_threads=128 [20090605-11:58:44.247763061] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090605-11:58:44.323787842] FFSB version 6.0-RC2.1 started [20090605-11:58:44.326204633] [20090605-11:58:44.856406381] benchmark time = 300 [20090605-11:58:44.858562796] ThreadGroup 0 [20090605-11:58:44.860910490] ================ [20090605-11:58:44.863073592] num_threads = 128 [20090605-11:58:44.865352071] [20090605-11:58:44.867344302] read_random = off [20090605-11:58:44.869156961] read_size = 0 (0B) [20090605-11:58:44.871216847] read_blocksize = 0 (0B) [20090605-11:58:44.873174586] read_skip = off [20090605-11:58:44.875248776] read_skipsize = 0 (0B) [20090605-11:58:44.877139359] [20090605-11:58:44.879173579] write_random = on [20090605-11:58:44.881105240] write_size = 5242880 (5MB) [20090605-11:58:44.883108672] fsync_file = 0 [20090605-11:58:44.885076882] write_blocksize = 4096 (4KB) [20090605-11:58:44.887102092] wait time = 0 [20090605-11:58:44.889024148] [20090605-11:58:44.891009853] op weights [20090605-11:58:44.892992182] read = 0 (0.00%) [20090605-11:58:44.894991762] readall = 0 (0.00%) [20090605-11:58:44.896900713] write = 1 (100.00%) [20090605-11:58:44.898871570] create = 0 (0.00%) [20090605-11:58:44.900805492] append = 0 (0.00%) [20090605-11:58:44.902799667] delete = 0 (0.00%) [20090605-11:58:44.904697224] metaop = 0 (0.00%) [20090605-11:58:44.906640840] createdir = 0 (0.00%) [20090605-11:58:44.908552503] stat = 0 (0.00%) [20090605-11:58:44.910615198] writeall = 0 (0.00%) [20090605-11:58:44.912550195] writeall_fsync = 0 (0.00%) [20090605-11:58:44.914565980] open_close = 0 (0.00%) [20090605-11:58:44.916653399] write_fsync = 0 (0.00%) [20090605-11:58:44.918579361] create_fsync = 0 (0.00%) [20090605-11:58:44.920598360] append_fsync = 0 (0.00%) [20090605-11:58:44.922621813] [20090605-11:58:44.924689640] FileSystem /mnt/ffsb1 [20090605-11:58:44.926586255] ========== [20090605-11:58:44.928543875] num_dirs = 0 [20090605-11:58:44.930427458] starting files = 1024 [20090605-11:58:44.932442796] [20090605-11:58:44.934352443] min file size = 104857600 (100MB) [20090605-11:58:44.936316202] max file size = 104857600 (100MB) [20090605-11:58:44.938231286] directio = on [20090605-11:58:44.940153789] alignedio = on [20090605-11:58:44.942137290] bufferedio = off [20090605-11:58:44.944092914] [20090605-11:58:44.946182842] aging is off [20090605-11:58:44.948133016] current utilization = 4.47% [20090605-11:58:44.950143270] [20090605-11:58:44.952233932] checking existing fs: /mnt/ffsb1 [20090605-11:58:45.025822135] fs setup took 0 secs [20090605-11:58:46.086016170] Syncing()...1 sec [20090605-11:58:46.091505835] Starting Actual Benchmark At: Fri Jun 5 11:58:46 2009 [20090605-11:58:46.107095150] [20090605-12:03:50.408362743] Syncing()...0 sec [20090605-12:03:50.411663105] FFSB benchmark finished at: Fri Jun 5 12:03:50 2009 [20090605-12:03:50.415022851] [20090605-12:03:50.418166249] Results: [20090605-12:03:50.436590799] Benchmark took 304.32 sec [20090605-12:03:50.439301457] [20090605-12:03:50.442268494] Total Results [20090605-12:03:50.461129070] =============== [20090605-12:03:50.464010332] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090605-12:03:50.466840562] ======= ============ ========= ======= =========== ========== [20090605-12:03:50.469595152] write : 8519680 27996.00 100.000% 100.000% 109MB/sec [20090605-12:03:50.472729511] - [20090605-12:03:50.475797137] 27996.00 Transactions per Second [20090605-12:03:50.481047219] [20090605-12:03:50.485155575] Throughput Results [20090605-12:03:50.504040590] =================== [20090605-12:03:50.506897641] Write Throughput: 109MB/sec [20090605-12:03:50.509939450] [20090605-12:03:50.513121039] System Call Latency statistics in millisecs [20090605-12:03:50.516291544] ===== [20090605-12:03:50.520487386] Min Avg Max Total Calls [20090605-12:03:50.525470787] ======== ======== ======== ============ [20090605-12:03:50.528683891] [ open] 0.007000 0.027358 0.700000 6656 [20090605-12:03:50.531796469] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-12:03:50.534836650] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-12:03:50.537755970] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-12:03:50.540542473] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-12:03:50.543163778] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-12:03:50.545880162] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-12:03:50.548854205] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-12:03:50.555016878] msec_range[7] 20.000000 - 50.000000 : 0 [20090605-12:03:50.560584672] msec_range[8] 10.000000 - 20.000000 : 0 [20090605-12:03:50.564213959] msec_range[9] 5.000000 - 10.000000 : 0 [20090605-12:03:50.567303049] msec_range[10] 2.000000 - 5.000000 : 0 [20090605-12:03:50.570675690] msec_range[11] 1.000000 - 2.000000 : 0 [20090605-12:03:50.573518857] msec_range[12] 0.500000 - 1.000000 : 4 [20090605-12:03:50.576210687] msec_range[13] 0.200000 - 0.500000 : 7 [20090605-12:03:50.579020014] msec_range[14] 0.100000 - 0.200000 : 13 [20090605-12:03:50.582192484] msec_range[15] 0.050000 - 0.100000 : 157 [20090605-12:03:50.586476232] msec_range[16] 0.020000 - 0.050000 : 5242 [20090605-12:03:50.589774322] msec_range[17] 0.010000 - 0.020000 : 1201 [20090605-12:03:50.592841685] msec_range[18] 0.000000 - 0.010000 : 32 [20090605-12:03:50.595587993] [20090605-12:03:50.598556390] [ write] 0.276000 4.550143 357.283997 8519680 [20090605-12:03:50.602565253] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-12:03:50.605762426] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-12:03:50.608941427] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-12:03:50.612551368] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-12:03:50.615686044] msec_range[4] 200.000000 - 500.000000 : 277 [20090605-12:03:50.618561969] msec_range[5] 100.000000 - 200.000000 : 591 [20090605-12:03:50.621372575] msec_range[6] 50.000000 - 100.000000 : 2758 [20090605-12:03:50.624897782] msec_range[7] 20.000000 - 50.000000 : 21693 [20090605-12:03:50.627939828] msec_range[8] 10.000000 - 20.000000 : 38349 [20090605-12:03:50.631059195] msec_range[9] 5.000000 - 10.000000 : 3321054 [20090605-12:03:50.634279960] msec_range[10] 2.000000 - 5.000000 : 3993067 [20090605-12:03:50.637329451] msec_range[11] 1.000000 - 2.000000 : 909991 [20090605-12:03:50.640419276] msec_range[12] 0.500000 - 1.000000 : 228040 [20090605-12:03:50.644514790] msec_range[13] 0.200000 - 0.500000 : 3860 [20090605-12:03:50.648611876] msec_range[14] 0.100000 - 0.200000 : 0 [20090605-12:03:50.652156222] msec_range[15] 0.050000 - 0.100000 : 0 [20090605-12:03:50.655304325] msec_range[16] 0.020000 - 0.050000 : 0 [20090605-12:03:50.659530951] msec_range[17] 0.010000 - 0.020000 : 0 [20090605-12:03:50.662621000] msec_range[18] 0.000000 - 0.010000 : 0 [20090605-12:03:50.665738241] [20090605-12:03:50.668530741] [ lseek] 0.000000 0.002690 36.938999 8519680 [20090605-12:03:50.671641840] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-12:03:50.674621572] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-12:03:50.678047747] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-12:03:50.682065066] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-12:03:50.685349964] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-12:03:50.688084588] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-12:03:50.692320398] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-12:03:50.695500272] msec_range[7] 20.000000 - 50.000000 : 1 [20090605-12:03:50.698783601] msec_range[8] 10.000000 - 20.000000 : 0 [20090605-12:03:50.701884048] msec_range[9] 5.000000 - 10.000000 : 0 [20090605-12:03:50.705056218] msec_range[10] 2.000000 - 5.000000 : 3 [20090605-12:03:50.708235189] msec_range[11] 1.000000 - 2.000000 : 49 [20090605-12:03:50.711353109] msec_range[12] 0.500000 - 1.000000 : 387 [20090605-12:03:50.714436389] msec_range[13] 0.200000 - 0.500000 : 2253 [20090605-12:03:50.717561951] msec_range[14] 0.100000 - 0.200000 : 7367 [20090605-12:03:50.720477757] msec_range[15] 0.050000 - 0.100000 : 14152 [20090605-12:03:50.723800778] msec_range[16] 0.020000 - 0.050000 : 23394 [20090605-12:03:50.727010596] msec_range[17] 0.010000 - 0.020000 : 51227 [20090605-12:03:50.730064442] msec_range[18] 0.000000 - 0.010000 : 8420847 [20090605-12:03:50.732802915] [20090605-12:03:50.735617250] [ close] 0.002000 0.008854 0.549000 6656 [20090605-12:03:50.738475627] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-12:03:50.741363425] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-12:03:50.744554430] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-12:03:50.749585671] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-12:03:50.752399265] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-12:03:50.755417814] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-12:03:50.757967141] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-12:03:50.760783184] msec_range[7] 20.000000 - 50.000000 : 0 [20090605-12:03:50.763609783] msec_range[8] 10.000000 - 20.000000 : 0 [20090605-12:03:50.766276947] msec_range[9] 5.000000 - 10.000000 : 0 [20090605-12:03:50.769122487] msec_range[10] 2.000000 - 5.000000 : 0 [20090605-12:03:50.772164902] msec_range[11] 1.000000 - 2.000000 : 0 [20090605-12:03:50.774946629] msec_range[12] 0.500000 - 1.000000 : 2 [20090605-12:03:50.777730051] msec_range[13] 0.200000 - 0.500000 : 2 [20090605-12:03:50.780974738] msec_range[14] 0.100000 - 0.200000 : 3 [20090605-12:03:50.783685772] msec_range[15] 0.050000 - 0.100000 : 15 [20090605-12:03:50.786487597] msec_range[16] 0.020000 - 0.050000 : 82 [20090605-12:03:50.789357297] msec_range[17] 0.010000 - 0.020000 : 1562 [20090605-12:03:50.791923289] msec_range[18] 0.000000 - 0.010000 : 4990 [20090605-12:03:50.794509659] [20090605-12:03:50.797156028] [20090605-12:03:50.800056038] [20090605-12:03:50.802934580] [20090605-12:03:50.805675351] 10.7% User Time [20090605-12:03:50.808346709] 533.0% System Time [20090605-12:03:50.810982315] 543.7% CPU Utilization [20090605-12:03:50.813973211] Profilers reporting [20090605-12:03:50.816854923] /autobench/scripts/doprofilers: line 2: 22157 Terminated ${CMDS[$i]} [20090605-12:03:50.819480639] /autobench/scripts/doprofilers: line 2: 22167 Terminated ${CMDS[$i]} [20090605-12:03:50.822308524] /autobench/scripts/doprofilers: line 2: 22203 Terminated ${CMDS[$i]} [20090605-12:04:02.712611625] Profilers postprocessing [20090605-12:04:02.830066113] Processing File : iostat.001 [20090605-12:04:02.832623197] Discovered iostat_interval=[5] [20090605-12:04:03.557097061] Processing Directory : sar.breakout.001 [20090605-12:04:03.559092308] Discovered sar_interval=[5] [20090605-12:04:03.730957219] Processing File : mpstat.001 [20090605-12:04:03.733371271] Discovered mpstat_interval=[5] [20090605-12:04:04.877378363] Stopping profiling. [20090605-12:04:04.884207313] Killing daemon. [20090605-12:04:06.069469465] Processing File : oprofile.001 [20090605-12:04:06.071782521] Processing File : oprofile-brief.001 [20090605-12:04:06.892798634] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-06-05_1047/btrfsnewformat-6-1-nodatacow' [20090605-12:04:11.678790135] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090605-12:04:11.898989196] PROCESSING COMMAND : 'mkfs.btrfs /dev/ffsbdev1' [20090605-12:04:11.939510666] [20090605-12:04:11.941780991] WARNING! - Btrfs v0.18-13-gb8420fa IS EXPERIMENTAL [20090605-12:04:11.944252725] WARNING! - see http://btrfs.wiki.kernel.org before using [20090605-12:04:11.946579705] [20090605-12:04:11.948608484] fs created label (null) on /dev/ffsbdev1 [20090605-12:04:11.950754805] nodesize 4096 leafsize 4096 sectorsize 4096 size 2.18TB [20090605-12:04:11.952678984] Btrfs v0.18-13-gb8420fa [20090605-12:04:12.009316643] PROCESSING COMMAND : 'mount -t btrfs -o nodatacow /dev/ffsbdev1 /mnt/ffsb1' [20090605-12:04:12.099000239] ONLY : Command [run large_file_creates__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/large_file_creates.ffsb reuse=1 num_threads=1] found for me [20090605-12:04:12.152933373] PROCESSING COMMAND : 'run large_file_creates__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/large_file_creates.ffsb reuse=1 num_threads=1' [20090605-12:04:12.201768422] new log requested [20090605-12:04:12.232848454] Running command ffsb [20090605-12:04:22.125303836] 06/05/2009-12:04:22 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/large_file_creates.ffsb Succeeded [20090605-12:04:22.136584493] Importing argument : reuse=1 [20090605-12:04:22.150215278] Importing argument : num_threads=1 [20090605-12:04:22.178680050] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090605-12:04:22.253474920] FFSB version 6.0-RC2.1 started [20090605-12:04:22.255786276] [20090605-12:04:22.258037899] benchmark time = 300 [20090605-12:04:22.260314582] ThreadGroup 0 [20090605-12:04:22.262727952] ================ [20090605-12:04:22.264729712] num_threads = 1 [20090605-12:04:22.267015208] [20090605-12:04:22.269084937] read_random = off [20090605-12:04:22.271177166] read_size = 0 (0B) [20090605-12:04:22.274150769] read_blocksize = 0 (0B) [20090605-12:04:22.276293627] read_skip = off [20090605-12:04:22.278466472] read_skipsize = 0 (0B) [20090605-12:04:22.280591672] [20090605-12:04:22.282594259] write_random = off [20090605-12:04:22.284528252] write_size = 0 (0B) [20090605-12:04:22.286601745] fsync_file = 0 [20090605-12:04:22.288541514] write_blocksize = 4096 (4KB) [20090605-12:04:22.290695499] wait time = 0 [20090605-12:04:22.292668871] [20090605-12:04:22.294696224] op weights [20090605-12:04:22.296721372] read = 0 (0.00%) [20090605-12:04:22.298627592] readall = 0 (0.00%) [20090605-12:04:22.300617621] write = 0 (0.00%) [20090605-12:04:22.302598314] create = 1 (100.00%) [20090605-12:04:22.304485655] append = 0 (0.00%) [20090605-12:04:22.306484620] delete = 0 (0.00%) [20090605-12:04:22.308501051] metaop = 0 (0.00%) [20090605-12:04:22.310496839] createdir = 0 (0.00%) [20090605-12:04:22.312434135] stat = 0 (0.00%) [20090605-12:04:22.314397831] writeall = 0 (0.00%) [20090605-12:04:22.322846606] writeall_fsync = 0 (0.00%) [20090605-12:04:22.324765895] open_close = 0 (0.00%) [20090605-12:04:22.326696437] write_fsync = 0 (0.00%) [20090605-12:04:22.328687569] create_fsync = 0 (0.00%) [20090605-12:04:22.330768336] append_fsync = 0 (0.00%) [20090605-12:04:22.332663243] [20090605-12:04:22.334609427] FileSystem /mnt/ffsb1 [20090605-12:04:22.336470874] ========== [20090605-12:04:22.338521328] num_dirs = 0 [20090605-12:04:22.340397332] starting files = 0 [20090605-12:04:22.342408471] [20090605-12:04:22.344435749] min file size = 1073741824 (1GB) [20090605-12:04:22.346374501] max file size = 1073741824 (1GB) [20090605-12:04:22.348390831] directio = off [20090605-12:04:22.350367035] alignedio = on [20090605-12:04:22.352446175] bufferedio = off [20090605-12:04:22.354319631] [20090605-12:04:22.356260367] aging is off [20090605-12:04:22.358229161] current utilization = 0.00% [20090605-12:04:22.360332700] [20090605-12:04:22.362255246] creating new fileset /mnt/ffsb1 [20090605-12:04:22.364246564] fs setup took 0 secs [20090605-12:04:23.422642621] Syncing()...1 sec [20090605-12:04:23.424673138] Starting Actual Benchmark At: Fri Jun 5 12:04:23 2009 [20090605-12:04:23.439462055] [20090605-12:09:32.413119902] Syncing()...1 sec [20090605-12:09:32.471813860] FFSB benchmark finished at: Fri Jun 5 12:09:31 2009 [20090605-12:09:32.476314335] [20090605-12:09:32.479593649] Results: [20090605-12:09:32.508204573] Benchmark took 308.53 sec [20090605-12:09:32.511203855] [20090605-12:09:32.514378087] Total Results [20090605-12:09:32.532637631] =============== [20090605-12:09:32.535507763] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090605-12:09:32.538451598] ======= ============ ========= ======= =========== ========== [20090605-12:09:32.541379837] create : 12320768 39934.37 100.000% 100.000% 156MB/sec [20090605-12:09:32.544237194] - [20090605-12:09:32.547082460] 39934.37 Transactions per Second [20090605-12:09:32.549851580] [20090605-12:09:32.552659004] Throughput Results [20090605-12:09:32.613090778] =================== [20090605-12:09:32.616265602] Write Throughput: 156MB/sec [20090605-12:09:32.619240938] [20090605-12:09:32.622836923] System Call Latency statistics in millisecs [20090605-12:09:32.626034990] ===== [20090605-12:09:32.629634417] Min Avg Max Total Calls [20090605-12:09:32.632546288] ======== ======== ======== ============ [20090605-12:09:32.636465584] [ open] 0.080000 0.131191 0.309000 47 [20090605-12:09:32.639752844] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-12:09:32.642841256] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-12:09:32.646052281] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-12:09:32.648968871] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-12:09:32.651899654] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-12:09:32.655052730] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-12:09:32.658241528] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-12:09:32.661195555] msec_range[7] 20.000000 - 50.000000 : 0 [20090605-12:09:32.663885956] msec_range[8] 10.000000 - 20.000000 : 0 [20090605-12:09:32.666960270] msec_range[9] 5.000000 - 10.000000 : 0 [20090605-12:09:32.670137838] msec_range[10] 2.000000 - 5.000000 : 0 [20090605-12:09:32.673831884] msec_range[11] 1.000000 - 2.000000 : 0 [20090605-12:09:32.678139506] msec_range[12] 0.500000 - 1.000000 : 0 [20090605-12:09:32.681435324] msec_range[13] 0.200000 - 0.500000 : 4 [20090605-12:09:32.684402870] msec_range[14] 0.100000 - 0.200000 : 35 [20090605-12:09:32.687197767] msec_range[15] 0.050000 - 0.100000 : 8 [20090605-12:09:32.690036521] msec_range[16] 0.020000 - 0.050000 : 0 [20090605-12:09:32.693280286] msec_range[17] 0.010000 - 0.020000 : 0 [20090605-12:09:32.696726155] msec_range[18] 0.000000 - 0.010000 : 0 [20090605-12:09:32.699870798] [20090605-12:09:32.705313205] [ write] 0.012000 0.024419 2.291000 12320768 [20090605-12:09:32.710160274] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-12:09:32.713470340] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-12:09:32.716372136] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-12:09:32.719002508] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-12:09:32.721706263] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-12:09:32.724603488] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-12:09:32.727986080] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-12:09:32.732459955] msec_range[7] 20.000000 - 50.000000 : 0 [20090605-12:09:32.735098985] msec_range[8] 10.000000 - 20.000000 : 0 [20090605-12:09:32.738124490] msec_range[9] 5.000000 - 10.000000 : 0 [20090605-12:09:32.742869607] msec_range[10] 2.000000 - 5.000000 : 2 [20090605-12:09:32.746110665] msec_range[11] 1.000000 - 2.000000 : 2 [20090605-12:09:32.749088829] msec_range[12] 0.500000 - 1.000000 : 9 [20090605-12:09:32.752232610] msec_range[13] 0.200000 - 0.500000 : 3078 [20090605-12:09:32.755527585] msec_range[14] 0.100000 - 0.200000 : 187 [20090605-12:09:32.758664207] msec_range[15] 0.050000 - 0.100000 : 258071 [20090605-12:09:32.761926500] msec_range[16] 0.020000 - 0.050000 : 7887745 [20090605-12:09:32.765154266] msec_range[17] 0.010000 - 0.020000 : 4171674 [20090605-12:09:32.768054658] msec_range[18] 0.000000 - 0.010000 : 0 [20090605-12:09:32.770801315] [20090605-12:09:32.773737358] [ close] 0.006000 0.008638 0.017000 47 [20090605-12:09:32.776659902] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090605-12:09:32.779609370] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090605-12:09:32.782743383] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090605-12:09:32.785881366] msec_range[3] 500.000000 - 1000.000000 : 0 [20090605-12:09:32.789687072] msec_range[4] 200.000000 - 500.000000 : 0 [20090605-12:09:32.792872335] msec_range[5] 100.000000 - 200.000000 : 0 [20090605-12:09:32.795971152] msec_range[6] 50.000000 - 100.000000 : 0 [20090605-12:09:32.798820458] msec_range[7] 20.000000 - 50.000000 : 0 [20090605-12:09:32.801991570] msec_range[8] 10.000000 - 20.000000 : 0 [20090605-12:09:32.805508899] msec_range[9] 5.000000 - 10.000000 : 0 [20090605-12:09:32.808882264] msec_range[10] 2.000000 - 5.000000 : 0 [20090605-12:09:32.812152272] msec_range[11] 1.000000 - 2.000000 : 0 [20090605-12:09:32.815029567] msec_range[12] 0.500000 - 1.000000 : 0 [20090605-12:09:32.818028064] msec_range[13] 0.200000 - 0.500000 : 0 [20090605-12:09:32.820971889] msec_range[14] 0.100000 - 0.200000 : 0 [20090605-12:09:32.824023811] msec_range[15] 0.050000 - 0.100000 : 0 [20090605-12:09:32.827029678] msec_range[16] 0.020000 - 0.050000 : 0 [20090605-12:09:32.829964419] msec_range[17] 0.010000 - 0.020000 : 10 [20090605-12:09:32.832818213] msec_range[18] 0.000000 - 0.010000 : 37 [20090605-12:09:32.836447141] [20090605-12:09:32.839353386] [20090605-12:09:32.844622521] [20090605-12:09:32.850517185] [20090605-12:09:32.854078799] 4.3% User Time [20090605-12:09:32.857044289] 95.1% System Time [20090605-12:09:32.860074241] 99.4% CPU Utilization [20090605-12:09:32.862825391] Profilers reporting [20090605-12:09:32.865699712] ls: /autobench/var/tmp//profilers_running: No such file or directory [20090605-12:09:47.551234161] Profilers postprocessing [20090605-12:09:47.808398946] Processing File : iostat.001 [20090605-12:09:47.810754278] Discovered iostat_interval=[5] [20090605-12:09:48.589123435] Processing Directory : sar.breakout.001 [20090605-12:09:48.591658333] Discovered sar_interval=[5] [20090605-12:09:48.766357040] Processing File : mpstat.001 [20090605-12:09:48.768568720] Discovered mpstat_interval=[5] [20090605-12:09:49.915139484] Stopping profiling. [20090605-12:09:49.922785692] Killing daemon. [20090605-12:09:52.198912458] Processing File : oprofile.001 [20090605-12:09:52.201289382] Processing File : oprofile-brief.001 [20090605-12:09:53.681343694] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-06-05_1047/btrfsnewformat-6-1-nodatacow'