[20090918-16:49:16.792754182] PROCESSING COMMAND : 'clearprofilers' [20090918-16:49:17.091932650] PROCESSING COMMAND : 'useprofiler iostat 5' [20090918-16:49:17.209781767] Checking for sar... [20090918-16:49:17.212155577] found [20090918-16:49:17.358892802] PROCESSING COMMAND : 'useprofiler sar 5' [20090918-16:49:17.476971841] Checking for sar... [20090918-16:49:17.479375785] found [20090918-16:49:17.628745263] PROCESSING COMMAND : 'useprofiler mpstat 5' [20090918-16:49:17.747633066] Checking for sar... [20090918-16:49:17.751475175] found [20090918-16:49:17.930774435] PROCESSING COMMAND : 'useprofiler oprofile' [20090918-16:49:18.117192114] Checking for gettext... [20090918-16:49:18.128980233] found [20090918-16:49:18.131227396] Checking for libiberty in autobench... [20090918-16:49:18.166648344] found [20090918-16:49:18.168917750] Checking for popt... [20090918-16:49:18.171174688] found [20090918-16:49:18.173336155] Checking for popt64... [20090918-16:49:18.175329079] found [20090918-16:49:18.177218635] Checking for oprofile... [20090918-16:49:18.192754151] found [20090918-16:49:18.261027122] opcontrol: oprofile 0.9.5cvs-P7 compiled on Jun 2 2009 12:44:23 [20090918-16:49:18.476164883] Daemon not running [20090918-16:49:26.846468588] OPROFILE : using callgraph [5] [20090918-16:49:27.087590116] Daemon not running [20090918-16:49:27.089911734] Separate options: none [20090918-16:49:27.092215087] vmlinux file: /boot/vmlinux-2.6.31-autokern1 [20090918-16:49:27.094586990] Image filter: none [20090918-16:49:27.096716515] Call-graph depth: 5 [20090918-16:49:27.315105636] PROCESSING COMMAND : 'umount /mnt/ffsb1 > /dev/null 2>&1' [20090918-16:49:27.397786413] PROCESSING COMMAND : 'set-sched noop' [20090918-16:49:27.719090684] PROCESSING COMMAND : 'mkresultdirs hks.austin.ibm.com benchmarks/results/btrfs/ffsb btrfs1 2009-09-18_1649 btrfsexp-9-18' [20090918-16:49:27.942424408] Connecting to hks.austin.ibm.com... [20090918-16:49:27.945004856] Remote working directory: /opt [20090918-16:49:27.947241454] Remote working directory: /opt/benchmarks/results/btrfs/ffsb [20090918-16:49:27.949560293] Couldn't create directory: Failure [20090918-16:49:27.951945308] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1 [20090918-16:49:27.954116851] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs1 [20090918-16:49:27.956469119] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1/2009-09-18_1649 [20090918-16:49:27.958632007] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs1/2009-09-18_1649 [20090918-16:49:27.960661799] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1/2009-09-18_1649/btrfsexp-9-18 [20090918-16:49:28.021457203] ONLY : Command [mkfs.btrfs 2>&1] found for me [20090918-16:49:28.073277914] PROCESSING COMMAND : 'mkfs.btrfs 2>&1' [20090918-16:49:28.104077920] usage: mkfs.btrfs [options] dev [ dev ... ] [20090918-16:49:28.106500151] options: [20090918-16:49:28.108732523] -A --alloc-start the offset to start the FS [20090918-16:49:28.111068504] -b --byte-count total number of bytes in the FS [20090918-16:49:28.113242734] -d --data data profile, raid0, raid1, raid10 or single [20090918-16:49:28.115214402] -l --leafsize size of btree leaves [20090918-16:49:28.117488636] -L --label set a label [20090918-16:49:28.119719194] -m --metadata metadata profile, values like data profile [20090918-16:49:28.121850424] -n --nodesize size of btree nodes [20090918-16:49:28.123806020] -s --sectorsize min block allocation [20090918-16:49:28.125870080] Btrfs v0.18-13-gb8420fa [20090918-16:49:28.204166939] PROCESSING COMMAND : 'mkfs.btrfs /dev/ffsbdev1' [20090918-16:49:28.239206986] [20090918-16:49:28.241402462] WARNING! - Btrfs v0.18-13-gb8420fa IS EXPERIMENTAL [20090918-16:49:28.243723298] WARNING! - see http://btrfs.wiki.kernel.org before using [20090918-16:49:28.245969469] [20090918-16:49:28.248049398] fs created label (null) on /dev/ffsbdev1 [20090918-16:49:28.250643295] nodesize 4096 leafsize 4096 sectorsize 4096 size 2.18TB [20090918-16:49:28.253082308] Btrfs v0.18-13-gb8420fa [20090918-16:49:28.419241990] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090918-16:49:28.699454680] 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 [20090918-16:49:28.752267166] 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' [20090918-16:49:28.807904928] new log requested [20090918-16:49:28.841796784] Running command ffsb [20090918-16:49:43.090594905] 09/18/2009-16:49:43 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb Succeeded [20090918-16:49:43.101606425] Importing argument : reuse=1 [20090918-16:49:43.114871110] Importing argument : num_threads=1 [20090918-16:49:43.144248789] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090918-16:49:43.245823150] FFSB version 6.0-RC2.1 started [20090918-16:49:43.248220844] [20090918-16:49:43.250569956] benchmark time = 300 [20090918-16:49:43.252813895] ThreadGroup 0 [20090918-16:49:43.255068670] ================ [20090918-16:49:43.257495700] num_threads = 1 [20090918-16:49:43.259547253] [20090918-16:49:43.261741722] read_random = off [20090918-16:49:43.263926893] read_size = 0 (0B) [20090918-16:49:43.266134386] read_blocksize = 4096 (4KB) [20090918-16:49:43.268121506] read_skip = off [20090918-16:49:43.270221775] read_skipsize = 0 (0B) [20090918-16:49:43.272365001] [20090918-16:49:43.274357380] write_random = off [20090918-16:49:43.276423627] write_size = 0 (0B) [20090918-16:49:43.278446781] fsync_file = 0 [20090918-16:49:43.280499517] write_blocksize = 0 (0B) [20090918-16:49:43.282447410] wait time = 0 [20090918-16:49:43.284525402] [20090918-16:49:43.286654212] op weights [20090918-16:49:43.288608217] read = 0 (0.00%) [20090918-16:49:43.290667625] readall = 1 (100.00%) [20090918-16:49:43.292648159] write = 0 (0.00%) [20090918-16:49:43.294654496] create = 0 (0.00%) [20090918-16:49:43.296570187] append = 0 (0.00%) [20090918-16:49:43.298682146] delete = 0 (0.00%) [20090918-16:49:43.300777944] metaop = 0 (0.00%) [20090918-16:49:43.302734193] createdir = 0 (0.00%) [20090918-16:49:43.304857342] stat = 0 (0.00%) [20090918-16:49:43.306888787] writeall = 0 (0.00%) [20090918-16:49:43.308938694] writeall_fsync = 0 (0.00%) [20090918-16:49:43.310891421] open_close = 0 (0.00%) [20090918-16:49:43.312995348] write_fsync = 0 (0.00%) [20090918-16:49:43.315112339] create_fsync = 0 (0.00%) [20090918-16:49:43.317096102] append_fsync = 0 (0.00%) [20090918-16:49:43.319178725] [20090918-16:49:43.321175949] FileSystem /mnt/ffsb1 [20090918-16:49:43.323255702] ========== [20090918-16:49:43.325234608] num_dirs = 0 [20090918-16:49:43.327361066] starting files = 1024 [20090918-16:49:43.329400818] [20090918-16:49:43.331397631] min file size = 104857600 (100MB) [20090918-16:49:43.333472161] max file size = 104857600 (100MB) [20090918-16:49:43.335506727] directio = off [20090918-16:49:43.337581629] alignedio = on [20090918-16:49:43.339555485] bufferedio = off [20090918-16:49:43.341648126] [20090918-16:49:43.343713116] aging is off [20090918-16:49:43.345660342] current utilization = 0.00% [20090918-16:49:43.347705421] [20090918-16:49:43.349701856] checking existing fs: /mnt/ffsb1 [20090918-16:49:43.351742060] opendir: No such file or directory [20090918-16:49:43.353671851] recreating new fileset [20090918-16:53:49.177467676] fs setup took 245 secs [20090918-16:54:22.078206862] Syncing()...32 sec [20090918-16:54:22.081059539] Starting Actual Benchmark At: Fri Sep 18 16:54:22 2009 [20090918-16:54:22.112742313] [20090918-16:59:24.238672532] Syncing()...1 sec [20090918-16:59:24.252512443] FFSB benchmark finished at: Fri Sep 18 16:59:24 2009 [20090918-16:59:24.255592429] [20090918-16:59:24.259271598] Results: [20090918-16:59:24.278765231] Benchmark took 302.11 sec [20090918-16:59:24.281384234] [20090918-16:59:24.284176923] Total Results [20090918-16:59:24.303398150] =============== [20090918-16:59:24.306407963] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090918-16:59:24.309148322] ======= ============ ========= ======= =========== ========== [20090918-16:59:24.316240629] readall : 18329600 60672.58 100.000% 100.000% 237MB/sec [20090918-16:59:24.320633162] - [20090918-16:59:24.324223705] 60672.58 Transactions per Second [20090918-16:59:24.327015647] [20090918-16:59:24.329889479] Throughput Results [20090918-16:59:24.349661437] =================== [20090918-16:59:24.352427803] Read Throughput: 237MB/sec [20090918-16:59:24.355128587] [20090918-16:59:24.358691185] System Call Latency statistics in millisecs [20090918-16:59:24.361460599] ===== [20090918-16:59:24.363972914] Min Avg Max Total Calls [20090918-16:59:24.366984559] ======== ======== ======== ============ [20090918-16:59:24.369818549] [ open] 0.021000 0.085559 4.030000 716 [20090918-16:59:24.372972526] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-16:59:24.376063504] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-16:59:24.378750976] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-16:59:24.381274260] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-16:59:24.384011736] msec_range[4] 200.000000 - 500.000000 : 0 [20090918-16:59:24.387464388] msec_range[5] 100.000000 - 200.000000 : 0 [20090918-16:59:24.394429692] msec_range[6] 50.000000 - 100.000000 : 0 [20090918-16:59:24.396965672] msec_range[7] 20.000000 - 50.000000 : 0 [20090918-16:59:24.399680300] msec_range[8] 10.000000 - 20.000000 : 0 [20090918-16:59:24.402302099] msec_range[9] 5.000000 - 10.000000 : 0 [20090918-16:59:24.406796439] msec_range[10] 2.000000 - 5.000000 : 2 [20090918-16:59:24.413078933] msec_range[11] 1.000000 - 2.000000 : 0 [20090918-16:59:24.417113268] msec_range[12] 0.500000 - 1.000000 : 0 [20090918-16:59:24.420034114] msec_range[13] 0.200000 - 0.500000 : 8 [20090918-16:59:24.423339374] msec_range[14] 0.100000 - 0.200000 : 87 [20090918-16:59:24.428044184] msec_range[15] 0.050000 - 0.100000 : 529 [20090918-16:59:24.432350525] msec_range[16] 0.020000 - 0.050000 : 90 [20090918-16:59:24.436792431] msec_range[17] 0.010000 - 0.020000 : 0 [20090918-16:59:24.440530288] msec_range[18] 0.000000 - 0.010000 : 0 [20090918-16:59:24.443698628] [20090918-16:59:24.446694465] [ read] 0.001000 0.016145 94.318001 18329600 [20090918-16:59:24.449285040] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-16:59:24.463307198] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-16:59:24.467075289] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-16:59:24.470443906] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-16:59:24.474372995] msec_range[4] 200.000000 - 500.000000 : 0 [20090918-16:59:24.477840094] msec_range[5] 100.000000 - 200.000000 : 0 [20090918-16:59:24.481075430] msec_range[6] 50.000000 - 100.000000 : 1 [20090918-16:59:24.484211311] msec_range[7] 20.000000 - 50.000000 : 197 [20090918-16:59:24.490581684] msec_range[8] 10.000000 - 20.000000 : 4497 [20090918-16:59:24.494148070] msec_range[9] 5.000000 - 10.000000 : 12798 [20090918-16:59:24.498086281] msec_range[10] 2.000000 - 5.000000 : 5067 [20090918-16:59:24.501291534] msec_range[11] 1.000000 - 2.000000 : 1831 [20090918-16:59:24.504287823] msec_range[12] 0.500000 - 1.000000 : 3375 [20090918-16:59:24.508598062] msec_range[13] 0.200000 - 0.500000 : 2076 [20090918-16:59:24.512237318] msec_range[14] 0.100000 - 0.200000 : 4107 [20090918-16:59:24.515459325] msec_range[15] 0.050000 - 0.100000 : 17179 [20090918-16:59:24.518762737] msec_range[16] 0.020000 - 0.050000 : 48171 [20090918-16:59:24.521421025] msec_range[17] 0.010000 - 0.020000 : 1101889 [20090918-16:59:24.524610656] msec_range[18] 0.000000 - 0.010000 : 17128412 [20090918-16:59:24.527750105] [20090918-16:59:24.530885647] [ close] 0.006000 0.009080 0.020000 716 [20090918-16:59:24.534192886] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-16:59:24.537331099] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-16:59:24.540036857] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-16:59:24.543069321] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-16:59:24.547258407] msec_range[4] 200.000000 - 500.000000 : 0 [20090918-16:59:24.550275819] msec_range[5] 100.000000 - 200.000000 : 0 [20090918-16:59:24.552910860] msec_range[6] 50.000000 - 100.000000 : 0 [20090918-16:59:24.556660788] msec_range[7] 20.000000 - 50.000000 : 0 [20090918-16:59:24.580895913] msec_range[8] 10.000000 - 20.000000 : 0 [20090918-16:59:24.585269271] msec_range[9] 5.000000 - 10.000000 : 0 [20090918-16:59:24.588165850] msec_range[10] 2.000000 - 5.000000 : 0 [20090918-16:59:24.591070034] msec_range[11] 1.000000 - 2.000000 : 0 [20090918-16:59:24.595379928] msec_range[12] 0.500000 - 1.000000 : 0 [20090918-16:59:24.599689668] msec_range[13] 0.200000 - 0.500000 : 0 [20090918-16:59:24.603920142] msec_range[14] 0.100000 - 0.200000 : 0 [20090918-16:59:24.607315895] msec_range[15] 0.050000 - 0.100000 : 0 [20090918-16:59:24.616306373] msec_range[16] 0.020000 - 0.050000 : 1 [20090918-16:59:24.619042489] msec_range[17] 0.010000 - 0.020000 : 172 [20090918-16:59:24.622186103] msec_range[18] 0.000000 - 0.010000 : 543 [20090918-16:59:24.629796640] [20090918-16:59:24.633474792] [20090918-16:59:24.637063362] [20090918-16:59:24.639963523] [20090918-16:59:24.644188086] 3.7% User Time [20090918-16:59:24.650781538] 80.6% System Time [20090918-16:59:24.654831148] 84.3% CPU Utilization [20090918-16:59:24.658800852] Profilers reporting [20090918-17:00:06.955374729] Profilers postprocessing [20090918-17:00:07.193618445] Processing File : iostat.001 [20090918-17:00:07.195936840] Discovered iostat_interval=[5] [20090918-17:00:08.018138577] Processing Directory : sar.breakout.001 [20090918-17:00:08.020631461] Discovered sar_interval=[5] [20090918-17:00:08.192982907] Processing File : mpstat.001 [20090918-17:00:08.195427215] Discovered mpstat_interval=[5] [20090918-17:00:09.344358620] Stopping profiling. [20090918-17:00:09.349711439] Killing daemon. [20090918-17:00:10.583415794] Processing File : oprofile.001 [20090918-17:00:10.585925665] Processing File : oprofile-brief.001 [20090918-17:00:14.969849537] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-09-18_1649/btrfsexp-9-18' [20090918-17:00:23.118157105] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090918-17:00:25.331885524] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090918-17:00:25.765887335] 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 [20090918-17:00:25.817762317] 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' [20090918-17:00:25.866941322] new log requested [20090918-17:00:25.907195615] Running command ffsb [20090918-17:00:37.058541033] 09/18/2009-17:00:37 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb Succeeded [20090918-17:00:37.070230944] Importing argument : reuse=1 [20090918-17:00:37.083530690] Importing argument : num_threads=16 [20090918-17:00:37.112505781] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090918-17:00:37.207167299] FFSB version 6.0-RC2.1 started [20090918-17:00:37.209133539] [20090918-17:00:37.272812509] benchmark time = 300 [20090918-17:00:37.275070296] ThreadGroup 0 [20090918-17:00:37.277301414] ================ [20090918-17:00:37.279352859] num_threads = 16 [20090918-17:00:37.281400907] [20090918-17:00:37.283321930] read_random = off [20090918-17:00:37.285297252] read_size = 0 (0B) [20090918-17:00:37.287419382] read_blocksize = 4096 (4KB) [20090918-17:00:37.289673568] read_skip = off [20090918-17:00:37.291815877] read_skipsize = 0 (0B) [20090918-17:00:37.293953758] [20090918-17:00:37.296050500] write_random = off [20090918-17:00:37.298098820] write_size = 0 (0B) [20090918-17:00:37.300027940] fsync_file = 0 [20090918-17:00:37.302169172] write_blocksize = 0 (0B) [20090918-17:00:37.304186074] wait time = 0 [20090918-17:00:37.306196504] [20090918-17:00:37.308095653] op weights [20090918-17:00:37.310146732] read = 0 (0.00%) [20090918-17:00:37.312147064] readall = 1 (100.00%) [20090918-17:00:37.314134829] write = 0 (0.00%) [20090918-17:00:37.316023719] create = 0 (0.00%) [20090918-17:00:37.318041200] append = 0 (0.00%) [20090918-17:00:37.319960713] delete = 0 (0.00%) [20090918-17:00:37.321918835] metaop = 0 (0.00%) [20090918-17:00:37.323792307] createdir = 0 (0.00%) [20090918-17:00:37.325727317] stat = 0 (0.00%) [20090918-17:00:37.327673813] writeall = 0 (0.00%) [20090918-17:00:37.329635934] writeall_fsync = 0 (0.00%) [20090918-17:00:37.331495304] open_close = 0 (0.00%) [20090918-17:00:37.333485325] write_fsync = 0 (0.00%) [20090918-17:00:37.335377780] create_fsync = 0 (0.00%) [20090918-17:00:37.337328829] append_fsync = 0 (0.00%) [20090918-17:00:37.339216587] [20090918-17:00:37.341549812] FileSystem /mnt/ffsb1 [20090918-17:00:37.343511485] ========== [20090918-17:00:37.345481240] num_dirs = 0 [20090918-17:00:37.347371687] starting files = 1024 [20090918-17:00:37.349453378] [20090918-17:00:37.351353213] min file size = 104857600 (100MB) [20090918-17:00:37.353300788] max file size = 104857600 (100MB) [20090918-17:00:37.355190779] directio = off [20090918-17:00:37.357213826] alignedio = on [20090918-17:00:37.359128297] bufferedio = off [20090918-17:00:37.361125009] [20090918-17:00:37.363003687] aging is off [20090918-17:00:37.365449943] current utilization = 4.48% [20090918-17:00:37.367391130] [20090918-17:00:37.369451534] checking existing fs: /mnt/ffsb1 [20090918-17:00:37.683845181] fs setup took 0 secs [20090918-17:00:39.238334117] Syncing()...1 sec [20090918-17:00:39.240761711] Starting Actual Benchmark At: Fri Sep 18 17:00:39 2009 [20090918-17:00:39.255836565] [20090918-17:05:44.369393974] Syncing()...2 sec [20090918-17:05:44.416882728] FFSB benchmark finished at: Fri Sep 18 17:05:43 2009 [20090918-17:05:44.420210555] [20090918-17:05:44.423682972] Results: [20090918-17:05:44.508917078] Benchmark took 304.65 sec [20090918-17:05:44.512025473] [20090918-17:05:44.514719924] Total Results [20090918-17:05:44.535115119] =============== [20090918-17:05:44.538240311] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090918-17:05:44.541503673] ======= ============ ========= ======= =========== ========== [20090918-17:05:44.544743460] readall : 46438400 152430.03 100.000% 100.000% 595MB/sec [20090918-17:05:44.547737819] - [20090918-17:05:44.550547694] 152430.03 Transactions per Second [20090918-17:05:44.553311509] [20090918-17:05:44.556246797] Throughput Results [20090918-17:05:44.582296639] =================== [20090918-17:05:44.605011958] Read Throughput: 595MB/sec [20090918-17:05:44.609076254] [20090918-17:05:44.612012723] System Call Latency statistics in millisecs [20090918-17:05:44.615179391] ===== [20090918-17:05:44.618288005] Min Avg Max Total Calls [20090918-17:05:44.621625379] ======== ======== ======== ============ [20090918-17:05:44.624687135] [ open] 0.007000 3.110433 727.848999 1814 [20090918-17:05:44.628644724] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-17:05:44.663007519] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-17:05:44.665913881] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-17:05:44.668889767] msec_range[3] 500.000000 - 1000.000000 : 1 [20090918-17:05:44.672236963] msec_range[4] 200.000000 - 500.000000 : 3 [20090918-17:05:44.674981220] msec_range[5] 100.000000 - 200.000000 : 9 [20090918-17:05:44.677684675] msec_range[6] 50.000000 - 100.000000 : 18 [20090918-17:05:44.684521611] msec_range[7] 20.000000 - 50.000000 : 32 [20090918-17:05:44.687506156] msec_range[8] 10.000000 - 20.000000 : 31 [20090918-17:05:44.690196845] msec_range[9] 5.000000 - 10.000000 : 25 [20090918-17:05:44.692925264] msec_range[10] 2.000000 - 5.000000 : 10 [20090918-17:05:44.695486833] msec_range[11] 1.000000 - 2.000000 : 2 [20090918-17:05:44.698297725] msec_range[12] 0.500000 - 1.000000 : 6 [20090918-17:05:44.700955269] msec_range[13] 0.200000 - 0.500000 : 37 [20090918-17:05:44.703635603] msec_range[14] 0.100000 - 0.200000 : 645 [20090918-17:05:44.706443716] msec_range[15] 0.050000 - 0.100000 : 557 [20090918-17:05:44.709214832] msec_range[16] 0.020000 - 0.050000 : 417 [20090918-17:05:44.711928224] msec_range[17] 0.010000 - 0.020000 : 11 [20090918-17:05:44.714701466] msec_range[18] 0.000000 - 0.010000 : 10 [20090918-17:05:44.717490740] [20090918-17:05:44.720376751] [ read] 0.001000 0.103306 3063.930908 46438400 [20090918-17:05:44.722983359] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-17:05:44.725723153] msec_range[1] 2000.000000 - 5000.000000 : 12 [20090918-17:05:44.728403642] msec_range[2] 1000.000000 - 2000.000000 : 114 [20090918-17:05:44.731072777] msec_range[3] 500.000000 - 1000.000000 : 128 [20090918-17:05:44.733704801] msec_range[4] 200.000000 - 500.000000 : 413 [20090918-17:05:44.736497915] msec_range[5] 100.000000 - 200.000000 : 6442 [20090918-17:05:44.739518753] msec_range[6] 50.000000 - 100.000000 : 20312 [20090918-17:05:44.742905153] msec_range[7] 20.000000 - 50.000000 : 34567 [20090918-17:05:44.745540327] msec_range[8] 10.000000 - 20.000000 : 26100 [20090918-17:05:44.748275393] msec_range[9] 5.000000 - 10.000000 : 28987 [20090918-17:05:44.750977131] msec_range[10] 2.000000 - 5.000000 : 18157 [20090918-17:05:44.753997327] msec_range[11] 1.000000 - 2.000000 : 17066 [20090918-17:05:44.757228821] msec_range[12] 0.500000 - 1.000000 : 9406 [20090918-17:05:44.760923032] msec_range[13] 0.200000 - 0.500000 : 8125 [20090918-17:05:44.764024973] msec_range[14] 0.100000 - 0.200000 : 7524 [20090918-17:05:44.766846783] msec_range[15] 0.050000 - 0.100000 : 21660 [20090918-17:05:44.769613498] msec_range[16] 0.020000 - 0.050000 : 779790 [20090918-17:05:44.772556667] msec_range[17] 0.010000 - 0.020000 : 5610670 [20090918-17:05:44.775226926] msec_range[18] 0.000000 - 0.010000 : 39848927 [20090918-17:05:44.777808734] [20090918-17:05:44.780729982] [ close] 0.003000 0.016217 6.509000 1814 [20090918-17:05:44.783362752] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-17:05:44.786136509] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-17:05:44.789372152] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-17:05:44.792728838] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-17:05:44.796266263] msec_range[4] 200.000000 - 500.000000 : 0 [20090918-17:05:44.799749638] msec_range[5] 100.000000 - 200.000000 : 0 [20090918-17:05:44.803453157] msec_range[6] 50.000000 - 100.000000 : 0 [20090918-17:05:44.806704508] msec_range[7] 20.000000 - 50.000000 : 0 [20090918-17:05:44.809613646] msec_range[8] 10.000000 - 20.000000 : 0 [20090918-17:05:44.812666604] msec_range[9] 5.000000 - 10.000000 : 1 [20090918-17:05:44.815660291] msec_range[10] 2.000000 - 5.000000 : 1 [20090918-17:05:44.818987019] msec_range[11] 1.000000 - 2.000000 : 1 [20090918-17:05:44.821713143] msec_range[12] 0.500000 - 1.000000 : 0 [20090918-17:05:44.824394661] msec_range[13] 0.200000 - 0.500000 : 0 [20090918-17:05:44.827067584] msec_range[14] 0.100000 - 0.200000 : 0 [20090918-17:05:44.830036129] msec_range[15] 0.050000 - 0.100000 : 1 [20090918-17:05:44.834145729] msec_range[16] 0.020000 - 0.050000 : 26 [20090918-17:05:44.837647728] msec_range[17] 0.010000 - 0.020000 : 931 [20090918-17:05:44.842022219] msec_range[18] 0.000000 - 0.010000 : 853 [20090918-17:05:44.845239983] [20090918-17:05:44.848456952] [20090918-17:05:44.851645234] [20090918-17:05:44.855228849] [20090918-17:05:44.857869997] 12.0% User Time [20090918-17:05:44.860650424] 248.0% System Time [20090918-17:05:44.863606786] 260.0% CPU Utilization [20090918-17:05:44.866813162] Profilers reporting [20090918-17:06:28.068187687] Profilers postprocessing [20090918-17:06:28.366171436] Processing File : iostat.001 [20090918-17:06:28.368404812] Discovered iostat_interval=[5] [20090918-17:06:29.157210531] Processing Directory : sar.breakout.001 [20090918-17:06:29.159611205] Discovered sar_interval=[5] [20090918-17:06:29.338805474] Processing File : mpstat.001 [20090918-17:06:29.341033973] Discovered mpstat_interval=[5] [20090918-17:06:30.486726796] Stopping profiling. [20090918-17:06:30.493829453] Killing daemon. [20090918-17:06:32.772308814] Processing File : oprofile.001 [20090918-17:06:32.774609180] Processing File : oprofile-brief.001 [20090918-17:06:37.399154434] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-09-18_1649/btrfsexp-9-18' [20090918-17:06:41.354292022] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090918-17:06:43.784733358] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090918-17:06:44.254067023] 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 [20090918-17:06:44.306494412] 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' [20090918-17:06:44.355049872] new log requested [20090918-17:06:44.399904893] Running command ffsb [20090918-17:06:56.274551550] 09/18/2009-17:06:56 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb Succeeded [20090918-17:06:56.285357142] Importing argument : reuse=1 [20090918-17:06:56.299276464] Importing argument : num_threads=128 [20090918-17:06:56.328329494] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090918-17:06:56.409140641] FFSB version 6.0-RC2.1 started [20090918-17:06:56.411081084] [20090918-17:06:56.959893889] benchmark time = 300 [20090918-17:06:56.962218734] ThreadGroup 0 [20090918-17:06:56.964468437] ================ [20090918-17:06:56.966811644] num_threads = 128 [20090918-17:06:56.968878875] [20090918-17:06:56.970877724] read_random = off [20090918-17:06:56.972873674] read_size = 0 (0B) [20090918-17:06:56.974826297] read_blocksize = 4096 (4KB) [20090918-17:06:56.976839056] read_skip = off [20090918-17:06:56.978788312] read_skipsize = 0 (0B) [20090918-17:06:56.980859885] [20090918-17:06:56.982797631] write_random = off [20090918-17:06:56.984813885] write_size = 0 (0B) [20090918-17:06:56.986779034] fsync_file = 0 [20090918-17:06:56.988835322] write_blocksize = 0 (0B) [20090918-17:06:56.990787986] wait time = 0 [20090918-17:06:56.992757457] [20090918-17:06:56.994694190] op weights [20090918-17:06:56.996701279] read = 0 (0.00%) [20090918-17:06:56.998617438] readall = 1 (100.00%) [20090918-17:06:57.000597495] write = 0 (0.00%) [20090918-17:06:57.002487846] create = 0 (0.00%) [20090918-17:06:57.004542774] append = 0 (0.00%) [20090918-17:06:57.006474099] delete = 0 (0.00%) [20090918-17:06:57.008464732] metaop = 0 (0.00%) [20090918-17:06:57.010524962] createdir = 0 (0.00%) [20090918-17:06:57.012526442] stat = 0 (0.00%) [20090918-17:06:57.014422080] writeall = 0 (0.00%) [20090918-17:06:57.016388467] writeall_fsync = 0 (0.00%) [20090918-17:06:57.018390139] open_close = 0 (0.00%) [20090918-17:06:57.020354838] write_fsync = 0 (0.00%) [20090918-17:06:57.022237930] create_fsync = 0 (0.00%) [20090918-17:06:57.024250470] append_fsync = 0 (0.00%) [20090918-17:06:57.026204309] [20090918-17:06:57.028172789] FileSystem /mnt/ffsb1 [20090918-17:06:57.030070965] ========== [20090918-17:06:57.032014499] num_dirs = 0 [20090918-17:06:57.033954002] starting files = 1024 [20090918-17:06:57.035914037] [20090918-17:06:57.037807901] min file size = 104857600 (100MB) [20090918-17:06:57.039794080] max file size = 104857600 (100MB) [20090918-17:06:57.041725120] directio = off [20090918-17:06:57.043716856] alignedio = on [20090918-17:06:57.045612837] bufferedio = off [20090918-17:06:57.047612872] [20090918-17:06:57.049580118] aging is off [20090918-17:06:57.051573836] current utilization = 4.48% [20090918-17:06:57.053483295] [20090918-17:06:57.055432710] checking existing fs: /mnt/ffsb1 [20090918-17:06:57.486282451] fs setup took 0 secs [20090918-17:06:59.178313071] Syncing()...1 sec [20090918-17:06:59.183833557] Starting Actual Benchmark At: Fri Sep 18 17:06:59 2009 [20090918-17:06:59.203579872] [20090918-17:12:12.661072225] Syncing()...1 sec [20090918-17:12:12.698783190] FFSB benchmark finished at: Fri Sep 18 17:12:12 2009 [20090918-17:12:12.702178136] [20090918-17:12:12.705559485] Results: [20090918-17:12:12.747892710] Benchmark took 312.97 sec [20090918-17:12:12.750743066] [20090918-17:12:12.753532659] Total Results [20090918-17:12:12.772626762] =============== [20090918-17:12:12.775140120] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090918-17:12:12.777906366] ======= ============ ========= ======= =========== ========== [20090918-17:12:12.781184421] readall : 42393600 135455.42 100.000% 100.000% 529MB/sec [20090918-17:12:12.784447121] - [20090918-17:12:12.787673084] 135455.42 Transactions per Second [20090918-17:12:12.790934797] [20090918-17:12:12.793997173] Throughput Results [20090918-17:12:12.810279427] =================== [20090918-17:12:12.813299225] Read Throughput: 529MB/sec [20090918-17:12:12.817231782] [20090918-17:12:12.820172711] System Call Latency statistics in millisecs [20090918-17:12:12.823078211] ===== [20090918-17:12:12.826077020] Min Avg Max Total Calls [20090918-17:12:12.828896360] ======== ======== ======== ============ [20090918-17:12:12.831469994] [ open] 0.007000 12.252090 1166.657959 1656 [20090918-17:12:12.834390691] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-17:12:12.837158015] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-17:12:12.839804669] msec_range[2] 1000.000000 - 2000.000000 : 1 [20090918-17:12:12.842653832] msec_range[3] 500.000000 - 1000.000000 : 4 [20090918-17:12:12.845490464] msec_range[4] 200.000000 - 500.000000 : 30 [20090918-17:12:12.848228203] msec_range[5] 100.000000 - 200.000000 : 20 [20090918-17:12:12.852763980] msec_range[6] 50.000000 - 100.000000 : 24 [20090918-17:12:12.868401261] msec_range[7] 20.000000 - 50.000000 : 49 [20090918-17:12:12.871172842] msec_range[8] 10.000000 - 20.000000 : 54 [20090918-17:12:12.873977950] msec_range[9] 5.000000 - 10.000000 : 31 [20090918-17:12:12.876937876] msec_range[10] 2.000000 - 5.000000 : 15 [20090918-17:12:12.879760320] msec_range[11] 1.000000 - 2.000000 : 3 [20090918-17:12:12.882384428] msec_range[12] 0.500000 - 1.000000 : 2 [20090918-17:12:12.885096830] msec_range[13] 0.200000 - 0.500000 : 18 [20090918-17:12:12.887728759] msec_range[14] 0.100000 - 0.200000 : 466 [20090918-17:12:12.890365684] msec_range[15] 0.050000 - 0.100000 : 340 [20090918-17:12:12.893048505] msec_range[16] 0.020000 - 0.050000 : 463 [20090918-17:12:12.895753510] msec_range[17] 0.010000 - 0.020000 : 66 [20090918-17:12:12.898394539] msec_range[18] 0.000000 - 0.010000 : 70 [20090918-17:12:12.900988525] [20090918-17:12:12.903541609] [ read] 0.001000 0.927278 44422.468750 42393600 [20090918-17:12:12.906281195] msec_range[0] 5000.000000 - 10000.000000 : 102 [20090918-17:12:12.908706724] msec_range[1] 2000.000000 - 5000.000000 : 199 [20090918-17:12:12.911125038] msec_range[2] 1000.000000 - 2000.000000 : 8973 [20090918-17:12:12.914003524] msec_range[3] 500.000000 - 1000.000000 : 17488 [20090918-17:12:12.916948863] msec_range[4] 200.000000 - 500.000000 : 19557 [20090918-17:12:12.919532358] msec_range[5] 100.000000 - 200.000000 : 11215 [20090918-17:12:12.921897456] msec_range[6] 50.000000 - 100.000000 : 11612 [20090918-17:12:12.924559565] msec_range[7] 20.000000 - 50.000000 : 17164 [20090918-17:12:12.927240375] msec_range[8] 10.000000 - 20.000000 : 15497 [20090918-17:12:12.929563608] msec_range[9] 5.000000 - 10.000000 : 19643 [20090918-17:12:12.931854076] msec_range[10] 2.000000 - 5.000000 : 15466 [20090918-17:12:12.934655969] msec_range[11] 1.000000 - 2.000000 : 22448 [20090918-17:12:12.937504326] msec_range[12] 0.500000 - 1.000000 : 7829 [20090918-17:12:12.940470161] msec_range[13] 0.200000 - 0.500000 : 5608 [20090918-17:12:12.944224674] msec_range[14] 0.100000 - 0.200000 : 8069 [20090918-17:12:12.947154054] msec_range[15] 0.050000 - 0.100000 : 17062 [20090918-17:12:12.950281082] msec_range[16] 0.020000 - 0.050000 : 685461 [20090918-17:12:12.953090310] msec_range[17] 0.010000 - 0.020000 : 5642777 [20090918-17:12:12.955840945] msec_range[18] 0.000000 - 0.010000 : 35867251 [20090918-17:12:12.958710919] [20090918-17:12:12.961504679] [ close] 0.003000 0.109868 33.555000 1656 [20090918-17:12:12.964170908] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-17:12:12.966940667] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-17:12:12.969241593] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-17:12:12.971709406] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-17:12:12.974511639] msec_range[4] 200.000000 - 500.000000 : 0 [20090918-17:12:12.978255457] msec_range[5] 100.000000 - 200.000000 : 0 [20090918-17:12:12.981384969] msec_range[6] 50.000000 - 100.000000 : 0 [20090918-17:12:12.985982585] msec_range[7] 20.000000 - 50.000000 : 2 [20090918-17:12:12.989210682] msec_range[8] 10.000000 - 20.000000 : 4 [20090918-17:12:12.992248488] msec_range[9] 5.000000 - 10.000000 : 4 [20090918-17:12:12.995227184] msec_range[10] 2.000000 - 5.000000 : 4 [20090918-17:12:12.998348442] msec_range[11] 1.000000 - 2.000000 : 2 [20090918-17:12:13.001147868] msec_range[12] 0.500000 - 1.000000 : 2 [20090918-17:12:13.011564044] msec_range[13] 0.200000 - 0.500000 : 4 [20090918-17:12:13.014618471] msec_range[14] 0.100000 - 0.200000 : 3 [20090918-17:12:13.017592677] msec_range[15] 0.050000 - 0.100000 : 3 [20090918-17:12:13.021046288] msec_range[16] 0.020000 - 0.050000 : 53 [20090918-17:12:13.024164365] msec_range[17] 0.010000 - 0.020000 : 807 [20090918-17:12:13.027395070] msec_range[18] 0.000000 - 0.010000 : 768 [20090918-17:12:13.030108708] [20090918-17:12:13.033359178] [20090918-17:12:13.036415616] [20090918-17:12:13.039297628] [20090918-17:12:13.041955918] 11.1% User Time [20090918-17:12:13.044903789] 242.8% System Time [20090918-17:12:13.048052110] 253.9% CPU Utilization [20090918-17:12:13.050888567] Profilers reporting [20090918-17:12:52.378967399] Profilers postprocessing [20090918-17:12:52.675985382] Processing File : iostat.001 [20090918-17:12:52.678472424] Discovered iostat_interval=[5] [20090918-17:12:53.467410248] Processing Directory : sar.breakout.001 [20090918-17:12:53.469595701] Discovered sar_interval=[5] [20090918-17:12:53.648929767] Processing File : mpstat.001 [20090918-17:12:53.651178372] Discovered mpstat_interval=[5] [20090918-17:12:54.819363491] Stopping profiling. [20090918-17:12:54.824617304] Killing daemon. [20090918-17:12:56.070962769] Processing File : oprofile.001 [20090918-17:12:56.073178115] Processing File : oprofile-brief.001 [20090918-17:13:00.778492507] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-09-18_1649/btrfsexp-9-18' [20090918-17:13:04.889864954] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090918-17:13:07.413846145] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090918-17:13:07.889153327] 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 [20090918-17:13:07.942173168] 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' [20090918-17:13:07.990722898] new log requested [20090918-17:13:08.033185122] Running command ffsb [20090918-17:13:20.319513990] 09/18/2009-17:13:20 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb Succeeded [20090918-17:13:20.330365361] Importing argument : reuse=1 [20090918-17:13:20.343640570] Importing argument : num_threads=1 [20090918-17:13:20.372961450] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090918-17:13:20.456430593] FFSB version 6.0-RC2.1 started [20090918-17:13:20.458700819] [20090918-17:13:20.460808966] benchmark time = 300 [20090918-17:13:20.463103632] ThreadGroup 0 [20090918-17:13:20.465275280] ================ [20090918-17:13:20.467477839] num_threads = 1 [20090918-17:13:20.469748437] [20090918-17:13:20.471784748] read_random = on [20090918-17:13:20.473790364] read_size = 5242880 (5MB) [20090918-17:13:20.475706906] read_blocksize = 4096 (4KB) [20090918-17:13:20.477701109] read_skip = off [20090918-17:13:20.479652197] read_skipsize = 0 (0B) [20090918-17:13:20.481644514] [20090918-17:13:20.483529539] write_random = off [20090918-17:13:20.485500451] write_size = 0 (0B) [20090918-17:13:20.487413079] fsync_file = 0 [20090918-17:13:20.489391656] write_blocksize = 0 (0B) [20090918-17:13:20.491265791] wait time = 0 [20090918-17:13:20.493244973] [20090918-17:13:20.495162927] op weights [20090918-17:13:20.497122872] read = 1 (100.00%) [20090918-17:13:20.498974556] readall = 0 (0.00%) [20090918-17:13:20.501157471] write = 0 (0.00%) [20090918-17:13:20.503329340] create = 0 (0.00%) [20090918-17:13:20.505275221] append = 0 (0.00%) [20090918-17:13:20.507361217] delete = 0 (0.00%) [20090918-17:13:20.509332501] metaop = 0 (0.00%) [20090918-17:13:20.511322678] createdir = 0 (0.00%) [20090918-17:13:20.513214228] stat = 0 (0.00%) [20090918-17:13:20.515231273] writeall = 0 (0.00%) [20090918-17:13:20.517143383] writeall_fsync = 0 (0.00%) [20090918-17:13:20.519104401] open_close = 0 (0.00%) [20090918-17:13:20.521005803] write_fsync = 0 (0.00%) [20090918-17:13:20.522973344] create_fsync = 0 (0.00%) [20090918-17:13:20.524885528] append_fsync = 0 (0.00%) [20090918-17:13:20.526846396] [20090918-17:13:20.528709603] FileSystem /mnt/ffsb1 [20090918-17:13:20.530681750] ========== [20090918-17:13:20.532565216] num_dirs = 0 [20090918-17:13:20.534530407] starting files = 1024 [20090918-17:13:20.536410551] [20090918-17:13:20.538350548] min file size = 104857600 (100MB) [20090918-17:13:20.540234569] max file size = 104857600 (100MB) [20090918-17:13:20.542228397] directio = off [20090918-17:13:20.544120543] alignedio = on [20090918-17:13:20.546185755] bufferedio = off [20090918-17:13:20.548220635] [20090918-17:13:20.550233967] aging is off [20090918-17:13:20.552105614] current utilization = 4.48% [20090918-17:13:20.554095845] [20090918-17:13:20.556059351] checking existing fs: /mnt/ffsb1 [20090918-17:13:21.037149554] fs setup took 0 secs [20090918-17:13:22.707027269] Syncing()...1 sec [20090918-17:13:22.709540569] Starting Actual Benchmark At: Fri Sep 18 17:13:22 2009 [20090918-17:13:22.724774749] [20090918-17:18:28.488246886] Syncing()...2 sec [20090918-17:18:28.491299065] FFSB benchmark finished at: Fri Sep 18 17:18:28 2009 [20090918-17:18:28.494325745] [20090918-17:18:28.497469325] Results: [20090918-17:18:28.513530454] Benchmark took 305.78 sec [20090918-17:18:28.516222239] [20090918-17:18:28.518971150] Total Results [20090918-17:18:28.538275858] =============== [20090918-17:18:28.543855188] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090918-17:18:28.546889064] ======= ============ ========= ======= =========== ========== [20090918-17:18:28.550321920] read : 168960 552.56 100.000% 100.000% 2.16MB/sec [20090918-17:18:28.553579212] - [20090918-17:18:28.557054629] 552.56 Transactions per Second [20090918-17:18:28.561228964] [20090918-17:18:28.565623160] Throughput Results [20090918-17:18:28.590619422] =================== [20090918-17:18:28.593547579] Read Throughput: 2.16MB/sec [20090918-17:18:28.598180993] [20090918-17:18:28.600795847] System Call Latency statistics in millisecs [20090918-17:18:28.603817919] ===== [20090918-17:18:28.607747892] Min Avg Max Total Calls [20090918-17:18:28.612323643] ======== ======== ======== ============ [20090918-17:18:28.617131317] [ open] 0.017000 0.029098 0.040000 132 [20090918-17:18:28.620625156] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-17:18:28.624985082] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-17:18:28.627899703] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-17:18:28.634495623] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-17:18:28.638098427] msec_range[4] 200.000000 - 500.000000 : 0 [20090918-17:18:28.640932279] msec_range[5] 100.000000 - 200.000000 : 0 [20090918-17:18:28.644221798] msec_range[6] 50.000000 - 100.000000 : 0 [20090918-17:18:28.651712303] msec_range[7] 20.000000 - 50.000000 : 0 [20090918-17:18:28.657888462] msec_range[8] 10.000000 - 20.000000 : 0 [20090918-17:18:28.667722960] msec_range[9] 5.000000 - 10.000000 : 0 [20090918-17:18:28.672146097] msec_range[10] 2.000000 - 5.000000 : 0 [20090918-17:18:28.677641646] msec_range[11] 1.000000 - 2.000000 : 0 [20090918-17:18:28.682036871] msec_range[12] 0.500000 - 1.000000 : 0 [20090918-17:18:28.686277419] msec_range[13] 0.200000 - 0.500000 : 0 [20090918-17:18:28.690676590] msec_range[14] 0.100000 - 0.200000 : 0 [20090918-17:18:28.694044405] msec_range[15] 0.050000 - 0.100000 : 0 [20090918-17:18:28.697021052] msec_range[16] 0.020000 - 0.050000 : 128 [20090918-17:18:28.699972607] msec_range[17] 0.010000 - 0.020000 : 4 [20090918-17:18:28.702513721] msec_range[18] 0.000000 - 0.010000 : 0 [20090918-17:18:28.706227616] [20090918-17:18:28.713690984] [ read] 0.002000 1.792772 79.139000 168960 [20090918-17:18:28.717538243] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-17:18:28.722075165] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-17:18:28.727329811] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-17:18:28.730816831] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-17:18:28.733991856] msec_range[4] 200.000000 - 500.000000 : 0 [20090918-17:18:28.740349950] msec_range[5] 100.000000 - 200.000000 : 0 [20090918-17:18:28.750700611] msec_range[6] 50.000000 - 100.000000 : 1 [20090918-17:18:28.754007313] msec_range[7] 20.000000 - 50.000000 : 112 [20090918-17:18:28.759231087] msec_range[8] 10.000000 - 20.000000 : 1103 [20090918-17:18:28.763083703] msec_range[9] 5.000000 - 10.000000 : 13566 [20090918-17:18:28.767706142] msec_range[10] 2.000000 - 5.000000 : 39972 [20090918-17:18:28.771685035] msec_range[11] 1.000000 - 2.000000 : 10226 [20090918-17:18:28.775156325] msec_range[12] 0.500000 - 1.000000 : 3396 [20090918-17:18:28.779534382] msec_range[13] 0.200000 - 0.500000 : 89768 [20090918-17:18:28.782735236] msec_range[14] 0.100000 - 0.200000 : 1 [20090918-17:18:28.786247526] msec_range[15] 0.050000 - 0.100000 : 0 [20090918-17:18:28.789743449] msec_range[16] 0.020000 - 0.050000 : 55 [20090918-17:18:28.792829764] msec_range[17] 0.010000 - 0.020000 : 1502 [20090918-17:18:28.795537883] msec_range[18] 0.000000 - 0.010000 : 9258 [20090918-17:18:28.798290885] [20090918-17:18:28.800956759] [ lseek] 0.000000 0.001423 1.709000 168960 [20090918-17:18:28.806841586] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-17:18:28.813091008] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-17:18:28.817501094] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-17:18:28.823402016] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-17:18:28.826686039] msec_range[4] 200.000000 - 500.000000 : 0 [20090918-17:18:28.829934496] msec_range[5] 100.000000 - 200.000000 : 0 [20090918-17:18:28.836824799] msec_range[6] 50.000000 - 100.000000 : 0 [20090918-17:18:28.840013424] msec_range[7] 20.000000 - 50.000000 : 0 [20090918-17:18:28.843276019] msec_range[8] 10.000000 - 20.000000 : 0 [20090918-17:18:28.847871271] msec_range[9] 5.000000 - 10.000000 : 0 [20090918-17:18:28.851110111] msec_range[10] 2.000000 - 5.000000 : 0 [20090918-17:18:28.855168636] msec_range[11] 1.000000 - 2.000000 : 1 [20090918-17:18:28.858299843] msec_range[12] 0.500000 - 1.000000 : 1 [20090918-17:18:28.861177844] msec_range[13] 0.200000 - 0.500000 : 0 [20090918-17:18:28.864606478] msec_range[14] 0.100000 - 0.200000 : 0 [20090918-17:18:28.868666781] msec_range[15] 0.050000 - 0.100000 : 0 [20090918-17:18:28.872435906] msec_range[16] 0.020000 - 0.050000 : 2 [20090918-17:18:28.875188575] msec_range[17] 0.010000 - 0.020000 : 180 [20090918-17:18:28.877795876] msec_range[18] 0.000000 - 0.010000 : 168776 [20090918-17:18:28.880394102] [20090918-17:18:28.883422134] [ close] 0.003000 0.007288 0.016000 132 [20090918-17:18:28.886873873] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-17:18:28.889623796] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-17:18:28.892428108] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-17:18:28.895466394] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-17:18:28.898460163] msec_range[4] 200.000000 - 500.000000 : 0 [20090918-17:18:28.902594248] msec_range[5] 100.000000 - 200.000000 : 0 [20090918-17:18:28.905444450] msec_range[6] 50.000000 - 100.000000 : 0 [20090918-17:18:28.908061416] msec_range[7] 20.000000 - 50.000000 : 0 [20090918-17:18:28.910983695] msec_range[8] 10.000000 - 20.000000 : 0 [20090918-17:18:28.915871977] msec_range[9] 5.000000 - 10.000000 : 0 [20090918-17:18:28.918535037] msec_range[10] 2.000000 - 5.000000 : 0 [20090918-17:18:28.921514403] msec_range[11] 1.000000 - 2.000000 : 0 [20090918-17:18:28.924244476] msec_range[12] 0.500000 - 1.000000 : 0 [20090918-17:18:28.927140370] msec_range[13] 0.200000 - 0.500000 : 0 [20090918-17:18:28.930342642] msec_range[14] 0.100000 - 0.200000 : 0 [20090918-17:18:28.933044900] msec_range[15] 0.050000 - 0.100000 : 0 [20090918-17:18:28.935255038] msec_range[16] 0.020000 - 0.050000 : 0 [20090918-17:18:28.937878820] msec_range[17] 0.010000 - 0.020000 : 19 [20090918-17:18:28.941037314] msec_range[18] 0.000000 - 0.010000 : 113 [20090918-17:18:28.943595360] [20090918-17:18:28.946390708] [20090918-17:18:28.949058654] [20090918-17:18:28.951589614] [20090918-17:18:28.953688755] 0.1% User Time [20090918-17:18:28.956172425] 4.0% System Time [20090918-17:18:28.959061799] 4.1% CPU Utilization [20090918-17:18:28.961682334] Profilers reporting [20090918-17:18:28.964435198] /autobench/scripts/doprofilers: line 2: 4641 Terminated ${CMDS[$i]} [20090918-17:18:58.255323380] Profilers postprocessing [20090918-17:18:58.375331626] Processing File : iostat.001 [20090918-17:18:58.377847170] Discovered iostat_interval=[5] [20090918-17:18:59.105900918] Processing Directory : sar.breakout.001 [20090918-17:18:59.108099498] Discovered sar_interval=[5] [20090918-17:18:59.281495225] Processing File : mpstat.001 [20090918-17:18:59.284119008] Discovered mpstat_interval=[5] [20090918-17:19:00.427151097] Stopping profiling. [20090918-17:19:00.431921266] Killing daemon. [20090918-17:19:01.627384844] Processing File : oprofile.001 [20090918-17:19:01.629846329] Processing File : oprofile-brief.001 [20090918-17:19:02.929349723] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-09-18_1649/btrfsexp-9-18' [20090918-17:19:05.670360714] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090918-17:19:06.995116466] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090918-17:19:07.460237682] 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 [20090918-17:19:07.513987294] 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' [20090918-17:19:07.562331103] new log requested [20090918-17:19:07.593608572] Running command ffsb [20090918-17:19:17.950040496] 09/18/2009-17:19:17 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb Succeeded [20090918-17:19:17.961124930] Importing argument : reuse=1 [20090918-17:19:17.974434070] Importing argument : num_threads=16 [20090918-17:19:18.003495519] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090918-17:19:18.078743688] FFSB version 6.0-RC2.1 started [20090918-17:19:18.080918539] [20090918-17:19:18.147158882] benchmark time = 300 [20090918-17:19:18.149527032] ThreadGroup 0 [20090918-17:19:18.151525806] ================ [20090918-17:19:18.153501409] num_threads = 16 [20090918-17:19:18.155432106] [20090918-17:19:18.157430290] read_random = on [20090918-17:19:18.159315299] read_size = 5242880 (5MB) [20090918-17:19:18.161284565] read_blocksize = 4096 (4KB) [20090918-17:19:18.163177413] read_skip = off [20090918-17:19:18.165143555] read_skipsize = 0 (0B) [20090918-17:19:18.167447819] [20090918-17:19:18.169738123] write_random = off [20090918-17:19:18.171997691] write_size = 0 (0B) [20090918-17:19:18.174272853] fsync_file = 0 [20090918-17:19:18.176448526] write_blocksize = 0 (0B) [20090918-17:19:18.178385186] wait time = 0 [20090918-17:19:18.180377530] [20090918-17:19:18.182343796] op weights [20090918-17:19:18.184607659] read = 1 (100.00%) [20090918-17:19:18.186523116] readall = 0 (0.00%) [20090918-17:19:18.188498837] write = 0 (0.00%) [20090918-17:19:18.190481631] create = 0 (0.00%) [20090918-17:19:18.192488926] append = 0 (0.00%) [20090918-17:19:18.194405059] delete = 0 (0.00%) [20090918-17:19:18.196363085] metaop = 0 (0.00%) [20090918-17:19:18.198531638] createdir = 0 (0.00%) [20090918-17:19:18.200526306] stat = 0 (0.00%) [20090918-17:19:18.202428668] writeall = 0 (0.00%) [20090918-17:19:18.204370464] writeall_fsync = 0 (0.00%) [20090918-17:19:18.206260689] open_close = 0 (0.00%) [20090918-17:19:18.208201473] write_fsync = 0 (0.00%) [20090918-17:19:18.210061291] create_fsync = 0 (0.00%) [20090918-17:19:18.211997974] append_fsync = 0 (0.00%) [20090918-17:19:18.213929319] [20090918-17:19:18.215899997] FileSystem /mnt/ffsb1 [20090918-17:19:18.217773996] ========== [20090918-17:19:18.219727307] num_dirs = 0 [20090918-17:19:18.221645319] starting files = 1024 [20090918-17:19:18.223608098] [20090918-17:19:18.225475308] min file size = 104857600 (100MB) [20090918-17:19:18.227413227] max file size = 104857600 (100MB) [20090918-17:19:18.229334811] directio = off [20090918-17:19:18.231317117] alignedio = on [20090918-17:19:18.233209490] bufferedio = off [20090918-17:19:18.235154648] [20090918-17:19:18.237113879] aging is off [20090918-17:19:18.239094880] current utilization = 4.48% [20090918-17:19:18.240970537] [20090918-17:19:18.242916441] checking existing fs: /mnt/ffsb1 [20090918-17:19:18.730157706] fs setup took 0 secs [20090918-17:19:20.502424456] Syncing()...1 sec [20090918-17:19:20.505080833] Starting Actual Benchmark At: Fri Sep 18 17:19:20 2009 [20090918-17:19:20.525855194] [20090918-17:24:26.733008165] Syncing()...1 sec [20090918-17:24:26.736205714] FFSB benchmark finished at: Fri Sep 18 17:24:26 2009 [20090918-17:24:26.739287371] [20090918-17:24:26.743170003] Results: [20090918-17:24:26.759239902] Benchmark took 306.12 sec [20090918-17:24:26.761934984] [20090918-17:24:26.764736194] Total Results [20090918-17:24:26.780915851] =============== [20090918-17:24:26.784519533] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090918-17:24:26.787716430] ======= ============ ========= ======= =========== ========== [20090918-17:24:26.790682177] read : 1422080 4645.42 100.000% 100.000% 18.1MB/sec [20090918-17:24:26.794010798] - [20090918-17:24:26.798231785] 4645.42 Transactions per Second [20090918-17:24:26.801140876] [20090918-17:24:26.803880798] Throughput Results [20090918-17:24:26.820329299] =================== [20090918-17:24:26.824115332] Read Throughput: 18.1MB/sec [20090918-17:24:26.827448798] [20090918-17:24:26.834804265] System Call Latency statistics in millisecs [20090918-17:24:26.838428874] ===== [20090918-17:24:26.841247336] Min Avg Max Total Calls [20090918-17:24:26.844792036] ======== ======== ======== ============ [20090918-17:24:26.847629263] [ open] 0.008000 0.059707 12.257000 1111 [20090918-17:24:26.850543233] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-17:24:26.853636027] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-17:24:26.856576725] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-17:24:26.858921487] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-17:24:26.861553470] msec_range[4] 200.000000 - 500.000000 : 0 [20090918-17:24:26.864243129] msec_range[5] 100.000000 - 200.000000 : 0 [20090918-17:24:26.866782618] msec_range[6] 50.000000 - 100.000000 : 0 [20090918-17:24:26.869194888] msec_range[7] 20.000000 - 50.000000 : 0 [20090918-17:24:26.871887627] msec_range[8] 10.000000 - 20.000000 : 1 [20090918-17:24:26.874631674] msec_range[9] 5.000000 - 10.000000 : 0 [20090918-17:24:26.877365353] msec_range[10] 2.000000 - 5.000000 : 0 [20090918-17:24:26.880641056] msec_range[11] 1.000000 - 2.000000 : 0 [20090918-17:24:26.884385576] msec_range[12] 0.500000 - 1.000000 : 0 [20090918-17:24:26.887906551] msec_range[13] 0.200000 - 0.500000 : 2 [20090918-17:24:26.892707470] msec_range[14] 0.100000 - 0.200000 : 59 [20090918-17:24:26.896626442] msec_range[15] 0.050000 - 0.100000 : 395 [20090918-17:24:26.900555255] msec_range[16] 0.020000 - 0.050000 : 603 [20090918-17:24:26.903789422] msec_range[17] 0.010000 - 0.020000 : 46 [20090918-17:24:26.908059452] msec_range[18] 0.000000 - 0.010000 : 5 [20090918-17:24:26.912094521] [20090918-17:24:26.915052959] [ read] 0.002000 3.404580 119.834000 1422080 [20090918-17:24:26.918247108] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-17:24:26.921220001] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-17:24:26.924280108] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-17:24:26.927759884] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-17:24:26.931008821] msec_range[4] 200.000000 - 500.000000 : 0 [20090918-17:24:26.934312466] msec_range[5] 100.000000 - 200.000000 : 4 [20090918-17:24:26.937296906] msec_range[6] 50.000000 - 100.000000 : 13 [20090918-17:24:26.940171141] msec_range[7] 20.000000 - 50.000000 : 1492 [20090918-17:24:26.943158870] msec_range[8] 10.000000 - 20.000000 : 23273 [20090918-17:24:26.945942670] msec_range[9] 5.000000 - 10.000000 : 335286 [20090918-17:24:26.948825231] msec_range[10] 2.000000 - 5.000000 : 616353 [20090918-17:24:26.951770200] msec_range[11] 1.000000 - 2.000000 : 56637 [20090918-17:24:26.954362499] msec_range[12] 0.500000 - 1.000000 : 94169 [20090918-17:24:26.957183961] msec_range[13] 0.200000 - 0.500000 : 166839 [20090918-17:24:26.960377027] msec_range[14] 0.100000 - 0.200000 : 113 [20090918-17:24:26.963062988] msec_range[15] 0.050000 - 0.100000 : 147 [20090918-17:24:26.965660986] msec_range[16] 0.020000 - 0.050000 : 2235 [20090918-17:24:26.968617751] msec_range[17] 0.010000 - 0.020000 : 17597 [20090918-17:24:26.971549546] msec_range[18] 0.000000 - 0.010000 : 107922 [20090918-17:24:26.974322581] [20090918-17:24:26.976869710] [ lseek] 0.000000 0.001628 4.000000 1422080 [20090918-17:24:26.985609766] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-17:24:26.988521647] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-17:24:26.991400452] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-17:24:26.994036720] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-17:24:26.997185130] msec_range[4] 200.000000 - 500.000000 : 0 [20090918-17:24:27.000175466] msec_range[5] 100.000000 - 200.000000 : 0 [20090918-17:24:27.002848220] msec_range[6] 50.000000 - 100.000000 : 0 [20090918-17:24:27.005313290] msec_range[7] 20.000000 - 50.000000 : 0 [20090918-17:24:27.008402836] msec_range[8] 10.000000 - 20.000000 : 0 [20090918-17:24:27.011378780] msec_range[9] 5.000000 - 10.000000 : 0 [20090918-17:24:27.014076743] msec_range[10] 2.000000 - 5.000000 : 4 [20090918-17:24:27.016631208] msec_range[11] 1.000000 - 2.000000 : 2 [20090918-17:24:27.019535900] msec_range[12] 0.500000 - 1.000000 : 10 [20090918-17:24:27.022417323] msec_range[13] 0.200000 - 0.500000 : 18 [20090918-17:24:27.024820198] msec_range[14] 0.100000 - 0.200000 : 58 [20090918-17:24:27.027319178] msec_range[15] 0.050000 - 0.100000 : 200 [20090918-17:24:27.030265748] msec_range[16] 0.020000 - 0.050000 : 680 [20090918-17:24:27.033475972] msec_range[17] 0.010000 - 0.020000 : 3349 [20090918-17:24:27.036658402] msec_range[18] 0.000000 - 0.010000 : 1417759 [20090918-17:24:27.042692848] [20090918-17:24:27.045464830] [ close] 0.003000 0.008173 0.042000 1111 [20090918-17:24:27.048037226] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-17:24:27.050412858] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-17:24:27.061993093] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-17:24:27.065829823] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-17:24:27.071867381] msec_range[4] 200.000000 - 500.000000 : 0 [20090918-17:24:27.076490260] msec_range[5] 100.000000 - 200.000000 : 0 [20090918-17:24:27.079414059] msec_range[6] 50.000000 - 100.000000 : 0 [20090918-17:24:27.082021570] msec_range[7] 20.000000 - 50.000000 : 0 [20090918-17:24:27.085096967] msec_range[8] 10.000000 - 20.000000 : 0 [20090918-17:24:27.088670690] msec_range[9] 5.000000 - 10.000000 : 0 [20090918-17:24:27.095829913] msec_range[10] 2.000000 - 5.000000 : 0 [20090918-17:24:27.099809407] msec_range[11] 1.000000 - 2.000000 : 0 [20090918-17:24:27.105322032] msec_range[12] 0.500000 - 1.000000 : 0 [20090918-17:24:27.109253597] msec_range[13] 0.200000 - 0.500000 : 0 [20090918-17:24:27.113750234] msec_range[14] 0.100000 - 0.200000 : 0 [20090918-17:24:27.121914252] msec_range[15] 0.050000 - 0.100000 : 0 [20090918-17:24:27.125218807] msec_range[16] 0.020000 - 0.050000 : 9 [20090918-17:24:27.128091698] msec_range[17] 0.010000 - 0.020000 : 172 [20090918-17:24:27.131703932] msec_range[18] 0.000000 - 0.010000 : 930 [20090918-17:24:27.137330128] [20090918-17:24:27.143652360] [20090918-17:24:27.146679882] [20090918-17:24:27.152813710] [20090918-17:24:27.157365964] 1.3% User Time [20090918-17:24:27.160955274] 39.0% System Time [20090918-17:24:27.170062225] 40.3% CPU Utilization [20090918-17:24:27.172469861] Profilers reporting [20090918-17:25:06.731858542] Profilers postprocessing [20090918-17:25:06.965105173] Processing File : iostat.001 [20090918-17:25:06.967532244] Discovered iostat_interval=[5] [20090918-17:25:07.753625273] Processing Directory : sar.breakout.001 [20090918-17:25:07.755796897] Discovered sar_interval=[5] [20090918-17:25:07.927765310] Processing File : mpstat.001 [20090918-17:25:07.930031957] Discovered mpstat_interval=[5] [20090918-17:25:09.075343537] Stopping profiling. [20090918-17:25:09.080014916] Killing daemon. [20090918-17:25:10.307862555] Processing File : oprofile.001 [20090918-17:25:10.311002393] Processing File : oprofile-brief.001 [20090918-17:25:13.144469190] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-09-18_1649/btrfsexp-9-18' [20090918-17:25:16.861467042] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090918-17:25:19.693838192] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090918-17:25:20.184698637] 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 [20090918-17:25:20.237994195] 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' [20090918-17:25:20.286477744] new log requested [20090918-17:25:20.316807497] Running command ffsb [20090918-17:25:31.303649143] 09/18/2009-17:25:31 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb Succeeded [20090918-17:25:31.315060660] Importing argument : reuse=1 [20090918-17:25:31.328649104] Importing argument : num_threads=128 [20090918-17:25:31.357496101] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090918-17:25:31.448877453] FFSB version 6.0-RC2.1 started [20090918-17:25:31.451218035] [20090918-17:25:31.998057150] benchmark time = 300 [20090918-17:25:32.000338653] ThreadGroup 0 [20090918-17:25:32.002742580] ================ [20090918-17:25:32.004962917] num_threads = 128 [20090918-17:25:32.007419346] [20090918-17:25:32.009443832] read_random = on [20090918-17:25:32.011439410] read_size = 5242880 (5MB) [20090918-17:25:32.013341915] read_blocksize = 4096 (4KB) [20090918-17:25:32.015346981] read_skip = off [20090918-17:25:32.017286390] read_skipsize = 0 (0B) [20090918-17:25:32.019267933] [20090918-17:25:32.021212985] write_random = off [20090918-17:25:32.023234093] write_size = 0 (0B) [20090918-17:25:32.025166348] fsync_file = 0 [20090918-17:25:32.027120775] write_blocksize = 0 (0B) [20090918-17:25:32.028990931] wait time = 0 [20090918-17:25:32.031032022] [20090918-17:25:32.033010319] op weights [20090918-17:25:32.034975930] read = 1 (100.00%) [20090918-17:25:32.036848458] readall = 0 (0.00%) [20090918-17:25:32.039041867] write = 0 (0.00%) [20090918-17:25:32.041072124] create = 0 (0.00%) [20090918-17:25:32.043135412] append = 0 (0.00%) [20090918-17:25:32.045376566] delete = 0 (0.00%) [20090918-17:25:32.047554812] metaop = 0 (0.00%) [20090918-17:25:32.049479123] createdir = 0 (0.00%) [20090918-17:25:32.051456563] stat = 0 (0.00%) [20090918-17:25:32.053378260] writeall = 0 (0.00%) [20090918-17:25:32.055369866] writeall_fsync = 0 (0.00%) [20090918-17:25:32.057271218] open_close = 0 (0.00%) [20090918-17:25:32.059228136] write_fsync = 0 (0.00%) [20090918-17:25:32.061139437] create_fsync = 0 (0.00%) [20090918-17:25:32.063135263] append_fsync = 0 (0.00%) [20090918-17:25:32.065012738] [20090918-17:25:32.066986024] FileSystem /mnt/ffsb1 [20090918-17:25:32.068864452] ========== [20090918-17:25:32.070850020] num_dirs = 0 [20090918-17:25:32.072725324] starting files = 1024 [20090918-17:25:32.074673463] [20090918-17:25:32.076555541] min file size = 104857600 (100MB) [20090918-17:25:32.078534946] max file size = 104857600 (100MB) [20090918-17:25:32.080413526] directio = off [20090918-17:25:32.082384658] alignedio = on [20090918-17:25:32.084274284] bufferedio = off [20090918-17:25:32.086238774] [20090918-17:25:32.088119304] aging is off [20090918-17:25:32.090087229] current utilization = 4.48% [20090918-17:25:32.091966473] [20090918-17:25:32.093950205] checking existing fs: /mnt/ffsb1 [20090918-17:25:32.577237855] fs setup took 0 secs [20090918-17:25:34.496875634] Syncing()...1 sec [20090918-17:25:34.502379321] Starting Actual Benchmark At: Fri Sep 18 17:25:34 2009 [20090918-17:25:34.520971175] [20090918-17:30:43.297703219] Syncing()...1 sec [20090918-17:30:43.300953965] FFSB benchmark finished at: Fri Sep 18 17:30:43 2009 [20090918-17:30:43.304137944] [20090918-17:30:43.307545878] Results: [20090918-17:30:43.327474403] Benchmark took 308.68 sec [20090918-17:30:43.330695073] [20090918-17:30:43.333972603] Total Results [20090918-17:30:43.353804661] =============== [20090918-17:30:43.357162128] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090918-17:30:43.360497272] ======= ============ ========= ======= =========== ========== [20090918-17:30:43.363262189] read : 5800960 18792.57 100.000% 100.000% 73.4MB/sec [20090918-17:30:43.366434137] - [20090918-17:30:43.369808731] 18792.57 Transactions per Second [20090918-17:30:43.373062393] [20090918-17:30:43.376993229] Throughput Results [20090918-17:30:43.398312749] =================== [20090918-17:30:43.402731923] Read Throughput: 73.4MB/sec [20090918-17:30:43.406255022] [20090918-17:30:43.409593198] System Call Latency statistics in millisecs [20090918-17:30:43.413479115] ===== [20090918-17:30:43.416786028] Min Avg Max Total Calls [20090918-17:30:43.421145722] ======== ======== ======== ============ [20090918-17:30:43.425209159] [ open] 0.007000 0.053627 11.366000 4532 [20090918-17:30:43.429860557] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-17:30:43.433218959] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-17:30:43.437174753] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-17:30:43.439994875] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-17:30:43.443009097] msec_range[4] 200.000000 - 500.000000 : 0 [20090918-17:30:43.446712186] msec_range[5] 100.000000 - 200.000000 : 0 [20090918-17:30:43.450902032] msec_range[6] 50.000000 - 100.000000 : 0 [20090918-17:30:43.461300720] msec_range[7] 20.000000 - 50.000000 : 0 [20090918-17:30:43.467045794] msec_range[8] 10.000000 - 20.000000 : 1 [20090918-17:30:43.472462777] msec_range[9] 5.000000 - 10.000000 : 1 [20090918-17:30:43.476466820] msec_range[10] 2.000000 - 5.000000 : 0 [20090918-17:30:43.479765837] msec_range[11] 1.000000 - 2.000000 : 0 [20090918-17:30:43.484507758] msec_range[12] 0.500000 - 1.000000 : 0 [20090918-17:30:43.488015954] msec_range[13] 0.200000 - 0.500000 : 7 [20090918-17:30:43.495832256] msec_range[14] 0.100000 - 0.200000 : 223 [20090918-17:30:43.499081640] msec_range[15] 0.050000 - 0.100000 : 1696 [20090918-17:30:43.504481717] msec_range[16] 0.020000 - 0.050000 : 2376 [20090918-17:30:43.512944352] msec_range[17] 0.010000 - 0.020000 : 155 [20090918-17:30:43.516755922] msec_range[18] 0.000000 - 0.010000 : 73 [20090918-17:30:43.520060865] [20090918-17:30:43.523103873] [ read] 0.001000 6.706033 656.341980 5800960 [20090918-17:30:43.526188973] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-17:30:43.528852590] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-17:30:43.532140283] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-17:30:43.536346037] msec_range[3] 500.000000 - 1000.000000 : 2 [20090918-17:30:43.540776529] msec_range[4] 200.000000 - 500.000000 : 151 [20090918-17:30:43.544688854] msec_range[5] 100.000000 - 200.000000 : 685 [20090918-17:30:43.551701318] msec_range[6] 50.000000 - 100.000000 : 3851 [20090918-17:30:43.555691573] msec_range[7] 20.000000 - 50.000000 : 140477 [20090918-17:30:43.559409934] msec_range[8] 10.000000 - 20.000000 : 818765 [20090918-17:30:43.562843997] msec_range[9] 5.000000 - 10.000000 : 2549877 [20090918-17:30:43.566363146] msec_range[10] 2.000000 - 5.000000 : 1661054 [20090918-17:30:43.569377669] msec_range[11] 1.000000 - 2.000000 : 48729 [20090918-17:30:43.572298451] msec_range[12] 0.500000 - 1.000000 : 28217 [20090918-17:30:43.575685774] msec_range[13] 0.200000 - 0.500000 : 3002 [20090918-17:30:43.578738581] msec_range[14] 0.100000 - 0.200000 : 293 [20090918-17:30:43.581672253] msec_range[15] 0.050000 - 0.100000 : 713 [20090918-17:30:43.584654289] msec_range[16] 0.020000 - 0.050000 : 23694 [20090918-17:30:43.587414753] msec_range[17] 0.010000 - 0.020000 : 86246 [20090918-17:30:43.590416701] msec_range[18] 0.000000 - 0.010000 : 435204 [20090918-17:30:43.594380346] [20090918-17:30:43.597393951] [ lseek] 0.000000 0.001838 2.153000 5800960 [20090918-17:30:43.600380150] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-17:30:43.607001025] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-17:30:43.610353295] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-17:30:43.614670019] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-17:30:43.618109061] msec_range[4] 200.000000 - 500.000000 : 0 [20090918-17:30:43.621069310] msec_range[5] 100.000000 - 200.000000 : 0 [20090918-17:30:43.624226713] msec_range[6] 50.000000 - 100.000000 : 0 [20090918-17:30:43.627306403] msec_range[7] 20.000000 - 50.000000 : 0 [20090918-17:30:43.630576008] msec_range[8] 10.000000 - 20.000000 : 0 [20090918-17:30:43.634535993] msec_range[9] 5.000000 - 10.000000 : 0 [20090918-17:30:43.637760989] msec_range[10] 2.000000 - 5.000000 : 1 [20090918-17:30:43.640884329] msec_range[11] 1.000000 - 2.000000 : 7 [20090918-17:30:43.644100431] msec_range[12] 0.500000 - 1.000000 : 6 [20090918-17:30:43.647751790] msec_range[13] 0.200000 - 0.500000 : 17 [20090918-17:30:43.651297684] msec_range[14] 0.100000 - 0.200000 : 89 [20090918-17:30:43.654878501] msec_range[15] 0.050000 - 0.100000 : 688 [20090918-17:30:43.658319315] msec_range[16] 0.020000 - 0.050000 : 9969 [20090918-17:30:43.661477759] msec_range[17] 0.010000 - 0.020000 : 26338 [20090918-17:30:43.664968066] msec_range[18] 0.000000 - 0.010000 : 5763845 [20090918-17:30:43.668022980] [20090918-17:30:43.671788376] [ close] 0.003000 0.009315 0.125000 4532 [20090918-17:30:43.674763627] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-17:30:43.677832303] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-17:30:43.681502838] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-17:30:43.685456360] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-17:30:43.689132380] msec_range[4] 200.000000 - 500.000000 : 0 [20090918-17:30:43.692595631] msec_range[5] 100.000000 - 200.000000 : 0 [20090918-17:30:43.696057329] msec_range[6] 50.000000 - 100.000000 : 0 [20090918-17:30:43.699381460] msec_range[7] 20.000000 - 50.000000 : 0 [20090918-17:30:43.702677666] msec_range[8] 10.000000 - 20.000000 : 0 [20090918-17:30:43.705917949] msec_range[9] 5.000000 - 10.000000 : 0 [20090918-17:30:43.709149770] msec_range[10] 2.000000 - 5.000000 : 0 [20090918-17:30:43.713680823] msec_range[11] 1.000000 - 2.000000 : 0 [20090918-17:30:43.717710273] msec_range[12] 0.500000 - 1.000000 : 0 [20090918-17:30:43.721098029] msec_range[13] 0.200000 - 0.500000 : 0 [20090918-17:30:43.724309024] msec_range[14] 0.100000 - 0.200000 : 2 [20090918-17:30:43.727787595] msec_range[15] 0.050000 - 0.100000 : 11 [20090918-17:30:43.731457090] msec_range[16] 0.020000 - 0.050000 : 113 [20090918-17:30:43.738429969] msec_range[17] 0.010000 - 0.020000 : 979 [20090918-17:30:43.742863933] msec_range[18] 0.000000 - 0.010000 : 3427 [20090918-17:30:43.746156284] [20090918-17:30:43.749125978] [20090918-17:30:43.752149652] [20090918-17:30:43.755333681] [20090918-17:30:43.758976209] 6.3% User Time [20090918-17:30:43.762377308] 194.6% System Time [20090918-17:30:43.765522450] 200.9% CPU Utilization [20090918-17:30:43.768791390] Profilers reporting [20090918-17:31:35.062939363] Profilers postprocessing [20090918-17:31:35.296034553] Processing File : iostat.001 [20090918-17:31:35.298418915] Discovered iostat_interval=[5] [20090918-17:31:36.082436487] Processing Directory : sar.breakout.001 [20090918-17:31:36.084617776] Discovered sar_interval=[5] [20090918-17:31:36.257835376] Processing File : mpstat.001 [20090918-17:31:36.260086864] Discovered mpstat_interval=[5] [20090918-17:31:37.405171409] Stopping profiling. [20090918-17:31:37.412100317] Killing daemon. [20090918-17:31:39.700203572] Processing File : oprofile.001 [20090918-17:31:39.702601604] Processing File : oprofile-brief.001 [20090918-17:31:42.508260238] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-09-18_1649/btrfsexp-9-18' [20090918-17:31:46.002271539] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090918-17:31:49.196221806] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090918-17:31:49.708376914] ONLY : Command [run random_writes__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb num_threads=1] found for me [20090918-17:31:49.760872554] PROCESSING COMMAND : 'run random_writes__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb num_threads=1' [20090918-17:31:49.809825528] new log requested [20090918-17:31:49.840334562] Running command ffsb [20090918-17:32:01.440532921] 09/18/2009-17:32:01 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb Succeeded [20090918-17:32:01.452045113] Importing argument : num_threads=1 [20090918-17:32:01.481276758] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090918-17:32:01.574886844] FFSB version 6.0-RC2.1 started [20090918-17:32:01.577185450] [20090918-17:32:01.579428436] benchmark time = 300 [20090918-17:32:01.581720825] ThreadGroup 0 [20090918-17:32:01.583895614] ================ [20090918-17:32:01.586220153] num_threads = 1 [20090918-17:32:01.588445145] [20090918-17:32:01.590621983] read_random = off [20090918-17:32:01.592620805] read_size = 0 (0B) [20090918-17:32:01.594696352] read_blocksize = 0 (0B) [20090918-17:32:01.596657741] read_skip = off [20090918-17:32:01.598810711] read_skipsize = 0 (0B) [20090918-17:32:01.601134627] [20090918-17:32:01.603218400] write_random = on [20090918-17:32:01.605113574] write_size = 5242880 (5MB) [20090918-17:32:01.607090804] fsync_file = 0 [20090918-17:32:01.609098385] write_blocksize = 4096 (4KB) [20090918-17:32:01.611071383] wait time = 0 [20090918-17:32:01.612948145] [20090918-17:32:01.614895948] op weights [20090918-17:32:01.616813861] read = 0 (0.00%) [20090918-17:32:01.618783177] readall = 0 (0.00%) [20090918-17:32:01.620667703] write = 1 (100.00%) [20090918-17:32:01.622637584] create = 0 (0.00%) [20090918-17:32:01.624498304] append = 0 (0.00%) [20090918-17:32:01.626491740] delete = 0 (0.00%) [20090918-17:32:01.628369399] metaop = 0 (0.00%) [20090918-17:32:01.630392810] createdir = 0 (0.00%) [20090918-17:32:01.632349480] stat = 0 (0.00%) [20090918-17:32:01.634312133] writeall = 0 (0.00%) [20090918-17:32:01.636211341] writeall_fsync = 0 (0.00%) [20090918-17:32:01.638181530] open_close = 0 (0.00%) [20090918-17:32:01.640108170] write_fsync = 0 (0.00%) [20090918-17:32:01.642054522] create_fsync = 0 (0.00%) [20090918-17:32:01.643913903] append_fsync = 0 (0.00%) [20090918-17:32:01.645939223] [20090918-17:32:01.647865975] FileSystem /mnt/ffsb1 [20090918-17:32:01.649810927] ========== [20090918-17:32:01.651659291] num_dirs = 0 [20090918-17:32:01.653554202] starting files = 1024 [20090918-17:32:01.655486387] [20090918-17:32:01.657442692] min file size = 104857600 (100MB) [20090918-17:32:01.659311939] max file size = 104857600 (100MB) [20090918-17:32:01.661319495] directio = off [20090918-17:32:01.663499038] alignedio = on [20090918-17:32:01.665442693] bufferedio = off [20090918-17:32:01.667299077] [20090918-17:32:01.669253773] aging is off [20090918-17:32:01.671338636] current utilization = 4.48% [20090918-17:32:01.673268980] [20090918-17:32:01.675125543] creating new fileset /mnt/ffsb1 [20090918-17:36:28.998682187] fs setup took 267 secs [20090918-17:37:02.954201877] Syncing()...34 sec [20090918-17:37:02.956780224] Starting Actual Benchmark At: Fri Sep 18 17:37:02 2009 [20090918-17:37:02.995352309] [20090918-17:42:17.098153065] Syncing()...12 sec [20090918-17:42:17.137067339] FFSB benchmark finished at: Fri Sep 18 17:42:16 2009 [20090918-17:42:17.140573558] [20090918-17:42:17.144151107] Results: [20090918-17:42:17.189025855] Benchmark took 313.77 sec [20090918-17:42:17.192026854] [20090918-17:42:17.195815137] Total Results [20090918-17:42:17.215174498] =============== [20090918-17:42:17.218147956] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090918-17:42:17.221476004] ======= ============ ========= ======= =========== ========== [20090918-17:42:17.225326657] write : 3345920 10663.74 100.000% 100.000% 41.7MB/sec [20090918-17:42:17.228466960] - [20090918-17:42:17.231326742] 10663.74 Transactions per Second [20090918-17:42:17.241522810] [20090918-17:42:17.245042342] Throughput Results [20090918-17:42:17.266267950] =================== [20090918-17:42:17.269270748] Write Throughput: 41.7MB/sec [20090918-17:42:17.272904517] [20090918-17:42:17.276193851] System Call Latency statistics in millisecs [20090918-17:42:17.279825416] ===== [20090918-17:42:17.282981830] Min Avg Max Total Calls [20090918-17:42:17.286099217] ======== ======== ======== ============ [20090918-17:42:17.289355938] [ open] 0.017000 0.109669 13.278000 2614 [20090918-17:42:17.292629860] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-17:42:17.295951172] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-17:42:17.299663485] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-17:42:17.302539784] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-17:42:17.306241585] msec_range[4] 200.000000 - 500.000000 : 0 [20090918-17:42:17.309695637] msec_range[5] 100.000000 - 200.000000 : 0 [20090918-17:42:17.312863617] msec_range[6] 50.000000 - 100.000000 : 0 [20090918-17:42:17.315779744] msec_range[7] 20.000000 - 50.000000 : 0 [20090918-17:42:17.319242415] msec_range[8] 10.000000 - 20.000000 : 1 [20090918-17:42:17.322417879] msec_range[9] 5.000000 - 10.000000 : 0 [20090918-17:42:17.326687080] msec_range[10] 2.000000 - 5.000000 : 7 [20090918-17:42:17.331287156] msec_range[11] 1.000000 - 2.000000 : 2 [20090918-17:42:17.334473082] msec_range[12] 0.500000 - 1.000000 : 5 [20090918-17:42:17.338293136] msec_range[13] 0.200000 - 0.500000 : 251 [20090918-17:42:17.342444964] msec_range[14] 0.100000 - 0.200000 : 790 [20090918-17:42:17.345810251] msec_range[15] 0.050000 - 0.100000 : 389 [20090918-17:42:17.349126027] msec_range[16] 0.020000 - 0.050000 : 1166 [20090918-17:42:17.352456105] msec_range[17] 0.010000 - 0.020000 : 3 [20090918-17:42:17.355821957] msec_range[18] 0.000000 - 0.010000 : 0 [20090918-17:42:17.358768855] [20090918-17:42:17.361864748] [ write] 0.006000 0.086962 9531.208984 3345920 [20090918-17:42:17.365598438] msec_range[0] 5000.000000 - 10000.000000 : 4 [20090918-17:42:17.368932888] msec_range[1] 2000.000000 - 5000.000000 : 14 [20090918-17:42:17.372298772] msec_range[2] 1000.000000 - 2000.000000 : 17 [20090918-17:42:17.375425177] msec_range[3] 500.000000 - 1000.000000 : 13 [20090918-17:42:17.378578351] msec_range[4] 200.000000 - 500.000000 : 51 [20090918-17:42:17.381947328] msec_range[5] 100.000000 - 200.000000 : 58 [20090918-17:42:17.384891630] msec_range[6] 50.000000 - 100.000000 : 552 [20090918-17:42:17.387898634] msec_range[7] 20.000000 - 50.000000 : 1145 [20090918-17:42:17.391029545] msec_range[8] 10.000000 - 20.000000 : 463 [20090918-17:42:17.394182518] msec_range[9] 5.000000 - 10.000000 : 761 [20090918-17:42:17.397153723] msec_range[10] 2.000000 - 5.000000 : 1179 [20090918-17:42:17.400199210] msec_range[11] 1.000000 - 2.000000 : 707 [20090918-17:42:17.403402637] msec_range[12] 0.500000 - 1.000000 : 665 [20090918-17:42:17.406811389] msec_range[13] 0.200000 - 0.500000 : 5585 [20090918-17:42:17.410542377] msec_range[14] 0.100000 - 0.200000 : 37414 [20090918-17:42:17.415550003] msec_range[15] 0.050000 - 0.100000 : 43463 [20090918-17:42:17.419842776] msec_range[16] 0.020000 - 0.050000 : 1138897 [20090918-17:42:17.423068845] msec_range[17] 0.010000 - 0.020000 : 2092031 [20090918-17:42:17.426219646] msec_range[18] 0.000000 - 0.010000 : 22901 [20090918-17:42:17.429443279] [20090918-17:42:17.433264601] [ lseek] 0.000000 0.001641 17.452999 3345920 [20090918-17:42:17.438452500] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-17:42:17.441791866] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-17:42:17.445085704] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-17:42:17.448595846] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-17:42:17.451605013] msec_range[4] 200.000000 - 500.000000 : 0 [20090918-17:42:17.454689675] msec_range[5] 100.000000 - 200.000000 : 0 [20090918-17:42:17.458106402] msec_range[6] 50.000000 - 100.000000 : 0 [20090918-17:42:17.461105115] msec_range[7] 20.000000 - 50.000000 : 0 [20090918-17:42:17.464070047] msec_range[8] 10.000000 - 20.000000 : 8 [20090918-17:42:17.467146072] msec_range[9] 5.000000 - 10.000000 : 27 [20090918-17:42:17.470052911] msec_range[10] 2.000000 - 5.000000 : 23 [20090918-17:42:17.472888719] msec_range[11] 1.000000 - 2.000000 : 35 [20090918-17:42:17.475765141] msec_range[12] 0.500000 - 1.000000 : 31 [20090918-17:42:17.478733866] msec_range[13] 0.200000 - 0.500000 : 26 [20090918-17:42:17.487660016] msec_range[14] 0.100000 - 0.200000 : 71 [20090918-17:42:17.490703210] msec_range[15] 0.050000 - 0.100000 : 325 [20090918-17:42:17.493648477] msec_range[16] 0.020000 - 0.050000 : 847 [20090918-17:42:17.496730243] msec_range[17] 0.010000 - 0.020000 : 9534 [20090918-17:42:17.500400285] msec_range[18] 0.000000 - 0.010000 : 3334993 [20090918-17:42:17.503326500] [20090918-17:42:17.506574090] [ close] 0.004000 0.009262 0.112000 2614 [20090918-17:42:17.510253589] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-17:42:17.513725687] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-17:42:17.516661194] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-17:42:17.519818352] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-17:42:17.522867095] msec_range[4] 200.000000 - 500.000000 : 0 [20090918-17:42:17.525919488] msec_range[5] 100.000000 - 200.000000 : 0 [20090918-17:42:17.528803386] msec_range[6] 50.000000 - 100.000000 : 0 [20090918-17:42:17.531965112] msec_range[7] 20.000000 - 50.000000 : 0 [20090918-17:42:17.535153735] msec_range[8] 10.000000 - 20.000000 : 0 [20090918-17:42:17.538324708] msec_range[9] 5.000000 - 10.000000 : 0 [20090918-17:42:17.541260308] msec_range[10] 2.000000 - 5.000000 : 0 [20090918-17:42:17.544386714] msec_range[11] 1.000000 - 2.000000 : 0 [20090918-17:42:17.547673776] msec_range[12] 0.500000 - 1.000000 : 0 [20090918-17:42:17.551334487] msec_range[13] 0.200000 - 0.500000 : 0 [20090918-17:42:17.554538016] msec_range[14] 0.100000 - 0.200000 : 2 [20090918-17:42:17.557487039] msec_range[15] 0.050000 - 0.100000 : 0 [20090918-17:42:17.563502151] msec_range[16] 0.020000 - 0.050000 : 38 [20090918-17:42:17.567053487] msec_range[17] 0.010000 - 0.020000 : 727 [20090918-17:42:17.571047893] msec_range[18] 0.000000 - 0.010000 : 1847 [20090918-17:42:17.575157471] [20090918-17:42:17.578828169] [20090918-17:42:17.590007107] [20090918-17:42:17.594337482] [20090918-17:42:17.599692638] 2.6% User Time [20090918-17:42:17.606170818] 27.3% System Time [20090918-17:42:17.610148228] 29.9% CPU Utilization [20090918-17:42:17.613630467] Profilers reporting [20090918-17:43:02.861511840] Profilers postprocessing [20090918-17:43:03.184836739] Processing File : iostat.001 [20090918-17:43:03.187204883] Discovered iostat_interval=[5] [20090918-17:43:03.990645865] Processing Directory : sar.breakout.001 [20090918-17:43:03.993168485] Discovered sar_interval=[5] [20090918-17:43:04.167129376] Processing File : mpstat.001 [20090918-17:43:04.169505191] Discovered mpstat_interval=[5] [20090918-17:43:05.317915441] Stopping profiling. [20090918-17:43:05.334441859] Killing daemon. [20090918-17:43:06.604713961] Processing File : oprofile.001 [20090918-17:43:06.606977741] Processing File : oprofile-brief.001 [20090918-17:43:11.330478242] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-09-18_1649/btrfsexp-9-18' [20090918-17:43:15.621080011] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090918-17:43:20.375349708] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090918-17:43:20.582913772] ONLY : Command [run random_writes__threads_0016 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb num_threads=16] found for me [20090918-17:43:20.635666651] PROCESSING COMMAND : 'run random_writes__threads_0016 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb num_threads=16' [20090918-17:43:20.684925300] new log requested [20090918-17:43:20.744422163] Running command ffsb [20090918-17:43:32.686604024] 09/18/2009-17:43:32 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb Succeeded [20090918-17:43:32.697574227] Importing argument : num_threads=16 [20090918-17:43:32.727211265] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090918-17:43:32.821093320] FFSB version 6.0-RC2.1 started [20090918-17:43:32.823293979] [20090918-17:43:32.889149060] benchmark time = 300 [20090918-17:43:32.891399094] ThreadGroup 0 [20090918-17:43:32.893524379] ================ [20090918-17:43:32.895866596] num_threads = 16 [20090918-17:43:32.898003628] [20090918-17:43:32.899871089] read_random = off [20090918-17:43:32.901998864] read_size = 0 (0B) [20090918-17:43:32.904274464] read_blocksize = 0 (0B) [20090918-17:43:32.906414062] read_skip = off [20090918-17:43:32.908436579] read_skipsize = 0 (0B) [20090918-17:43:32.910525163] [20090918-17:43:32.912484579] write_random = on [20090918-17:43:32.914481584] write_size = 5242880 (5MB) [20090918-17:43:32.916452953] fsync_file = 0 [20090918-17:43:32.918406346] write_blocksize = 4096 (4KB) [20090918-17:43:32.920314601] wait time = 0 [20090918-17:43:32.922304457] [20090918-17:43:32.924222110] op weights [20090918-17:43:32.926154603] read = 0 (0.00%) [20090918-17:43:32.928004759] readall = 0 (0.00%) [20090918-17:43:32.929973112] write = 1 (100.00%) [20090918-17:43:32.932109131] create = 0 (0.00%) [20090918-17:43:32.934282503] append = 0 (0.00%) [20090918-17:43:32.936244173] delete = 0 (0.00%) [20090918-17:43:32.938583672] metaop = 0 (0.00%) [20090918-17:43:32.940765684] createdir = 0 (0.00%) [20090918-17:43:32.942703893] stat = 0 (0.00%) [20090918-17:43:32.944765391] writeall = 0 (0.00%) [20090918-17:43:32.949296863] writeall_fsync = 0 (0.00%) [20090918-17:43:32.951822650] open_close = 0 (0.00%) [20090918-17:43:32.953769203] write_fsync = 0 (0.00%) [20090918-17:43:32.955815762] create_fsync = 0 (0.00%) [20090918-17:43:32.957805985] append_fsync = 0 (0.00%) [20090918-17:43:32.959834147] [20090918-17:43:32.961777441] FileSystem /mnt/ffsb1 [20090918-17:43:32.963939376] ========== [20090918-17:43:32.966083360] num_dirs = 0 [20090918-17:43:32.968013210] starting files = 1024 [20090918-17:43:32.969999315] [20090918-17:43:32.972064055] min file size = 104857600 (100MB) [20090918-17:43:32.974075528] max file size = 104857600 (100MB) [20090918-17:43:32.975980769] directio = off [20090918-17:43:32.977975244] alignedio = on [20090918-17:43:32.979900963] bufferedio = off [20090918-17:43:32.981879715] [20090918-17:43:32.983750902] aging is off [20090918-17:43:32.985753001] current utilization = 4.96% [20090918-17:43:32.988104025] [20090918-17:43:32.990133356] creating new fileset /mnt/ffsb1 [20090918-17:55:34.689861627] fs setup took 721 secs [20090918-17:55:57.010651197] Syncing()...22 sec [20090918-17:55:57.013347985] Starting Actual Benchmark At: Fri Sep 18 17:55:57 2009 [20090918-17:55:57.055555623] [20090918-18:01:19.664758234] Syncing()...20 sec [20090918-18:01:19.703713375] FFSB benchmark finished at: Fri Sep 18 18:01:19 2009 [20090918-18:01:19.706803627] [20090918-18:01:19.710387995] Results: [20090918-18:01:19.741998600] Benchmark took 322.44 sec [20090918-18:01:19.745464524] [20090918-18:01:19.748766887] Total Results [20090918-18:01:19.768185905] =============== [20090918-18:01:19.771158487] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090918-18:01:19.774282227] ======= ============ ========= ======= =========== ========== [20090918-18:01:19.777763032] write : 3406080 10563.55 100.000% 100.000% 41.3MB/sec [20090918-18:01:19.780773541] - [20090918-18:01:19.783422641] 10563.55 Transactions per Second [20090918-18:01:19.786393501] [20090918-18:01:19.789135495] Throughput Results [20090918-18:01:19.804583462] =================== [20090918-18:01:19.807474090] Write Throughput: 41.3MB/sec [20090918-18:01:19.810070306] [20090918-18:01:19.812409495] System Call Latency statistics in millisecs [20090918-18:01:19.815469361] ===== [20090918-18:01:19.818049736] Min Avg Max Total Calls [20090918-18:01:19.820634178] ======== ======== ======== ============ [20090918-18:01:19.824469176] [ open] 0.014000 0.237239 23.820999 2661 [20090918-18:01:19.829960918] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-18:01:19.833340370] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-18:01:19.837254438] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-18:01:19.840798343] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-18:01:19.843817349] msec_range[4] 200.000000 - 500.000000 : 0 [20090918-18:01:19.846634835] msec_range[5] 100.000000 - 200.000000 : 0 [20090918-18:01:19.849502999] msec_range[6] 50.000000 - 100.000000 : 0 [20090918-18:01:19.852472514] msec_range[7] 20.000000 - 50.000000 : 7 [20090918-18:01:19.855252214] msec_range[8] 10.000000 - 20.000000 : 5 [20090918-18:01:19.857890349] msec_range[9] 5.000000 - 10.000000 : 3 [20090918-18:01:19.860693003] msec_range[10] 2.000000 - 5.000000 : 8 [20090918-18:01:19.863615465] msec_range[11] 1.000000 - 2.000000 : 10 [20090918-18:01:19.868938031] msec_range[12] 0.500000 - 1.000000 : 34 [20090918-18:01:19.873441966] msec_range[13] 0.200000 - 0.500000 : 530 [20090918-18:01:19.876821709] msec_range[14] 0.100000 - 0.200000 : 762 [20090918-18:01:19.881069590] msec_range[15] 0.050000 - 0.100000 : 294 [20090918-18:01:19.884136314] msec_range[16] 0.020000 - 0.050000 : 981 [20090918-18:01:19.887028853] msec_range[17] 0.010000 - 0.020000 : 27 [20090918-18:01:19.889758777] msec_range[18] 0.000000 - 0.010000 : 0 [20090918-18:01:19.892455827] [20090918-18:01:19.895649743] [ write] 0.006000 1.382476 21479.591797 3406080 [20090918-18:01:19.898344220] msec_range[0] 5000.000000 - 10000.000000 : 93 [20090918-18:01:19.900924191] msec_range[1] 2000.000000 - 5000.000000 : 145 [20090918-18:01:19.903406013] msec_range[2] 1000.000000 - 2000.000000 : 147 [20090918-18:01:19.906445897] msec_range[3] 500.000000 - 1000.000000 : 552 [20090918-18:01:19.909147996] msec_range[4] 200.000000 - 500.000000 : 2701 [20090918-18:01:19.911618781] msec_range[5] 100.000000 - 200.000000 : 3341 [20090918-18:01:19.914595958] msec_range[6] 50.000000 - 100.000000 : 3742 [20090918-18:01:19.917245698] msec_range[7] 20.000000 - 50.000000 : 5240 [20090918-18:01:19.919743242] msec_range[8] 10.000000 - 20.000000 : 4042 [20090918-18:01:19.922185689] msec_range[9] 5.000000 - 10.000000 : 3988 [20090918-18:01:19.925207647] msec_range[10] 2.000000 - 5.000000 : 4502 [20090918-18:01:19.928298963] msec_range[11] 1.000000 - 2.000000 : 2747 [20090918-18:01:19.932100330] msec_range[12] 0.500000 - 1.000000 : 3143 [20090918-18:01:19.934965660] msec_range[13] 0.200000 - 0.500000 : 33476 [20090918-18:01:19.937896430] msec_range[14] 0.100000 - 0.200000 : 91449 [20090918-18:01:19.940730470] msec_range[15] 0.050000 - 0.100000 : 196886 [20090918-18:01:19.943828421] msec_range[16] 0.020000 - 0.050000 : 2307199 [20090918-18:01:19.947011809] msec_range[17] 0.010000 - 0.020000 : 742333 [20090918-18:01:19.950054403] msec_range[18] 0.000000 - 0.010000 : 266 [20090918-18:01:19.953120597] [20090918-18:01:19.955852224] [ lseek] 0.000000 0.029937 15114.524414 3406080 [20090918-18:01:19.958446686] msec_range[0] 5000.000000 - 10000.000000 : 1 [20090918-18:01:19.961703334] msec_range[1] 2000.000000 - 5000.000000 : 6 [20090918-18:01:19.964868691] msec_range[2] 1000.000000 - 2000.000000 : 4 [20090918-18:01:19.967872830] msec_range[3] 500.000000 - 1000.000000 : 6 [20090918-18:01:19.970969590] msec_range[4] 200.000000 - 500.000000 : 13 [20090918-18:01:19.980550819] msec_range[5] 100.000000 - 200.000000 : 11 [20090918-18:01:19.984783366] msec_range[6] 50.000000 - 100.000000 : 19 [20090918-18:01:19.988341166] msec_range[7] 20.000000 - 50.000000 : 37 [20090918-18:01:19.993443368] msec_range[8] 10.000000 - 20.000000 : 39 [20090918-18:01:19.996746846] msec_range[9] 5.000000 - 10.000000 : 64 [20090918-18:01:20.000782877] msec_range[10] 2.000000 - 5.000000 : 73 [20090918-18:01:20.004306331] msec_range[11] 1.000000 - 2.000000 : 78 [20090918-18:01:20.007064137] msec_range[12] 0.500000 - 1.000000 : 90 [20090918-18:01:20.010468616] msec_range[13] 0.200000 - 0.500000 : 145 [20090918-18:01:20.013547032] msec_range[14] 0.100000 - 0.200000 : 327 [20090918-18:01:20.019371123] msec_range[15] 0.050000 - 0.100000 : 1266 [20090918-18:01:20.024767334] msec_range[16] 0.020000 - 0.050000 : 11463 [20090918-18:01:20.030126801] msec_range[17] 0.010000 - 0.020000 : 26639 [20090918-18:01:20.034467069] msec_range[18] 0.000000 - 0.010000 : 3365795 [20090918-18:01:20.038983489] [20090918-18:01:20.042619825] [ close] 0.004000 0.023248 22.934999 2661 [20090918-18:01:20.045787307] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-18:01:20.048958275] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-18:01:20.052005390] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-18:01:20.054856062] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-18:01:20.058277010] msec_range[4] 200.000000 - 500.000000 : 0 [20090918-18:01:20.062456170] msec_range[5] 100.000000 - 200.000000 : 0 [20090918-18:01:20.066304302] msec_range[6] 50.000000 - 100.000000 : 0 [20090918-18:01:20.073324144] msec_range[7] 20.000000 - 50.000000 : 1 [20090918-18:01:20.076428217] msec_range[8] 10.000000 - 20.000000 : 0 [20090918-18:01:20.080482023] msec_range[9] 5.000000 - 10.000000 : 0 [20090918-18:01:20.084064894] msec_range[10] 2.000000 - 5.000000 : 1 [20090918-18:01:20.087107224] msec_range[11] 1.000000 - 2.000000 : 2 [20090918-18:01:20.089700110] msec_range[12] 0.500000 - 1.000000 : 0 [20090918-18:01:20.092913413] msec_range[13] 0.200000 - 0.500000 : 0 [20090918-18:01:20.096044140] msec_range[14] 0.100000 - 0.200000 : 1 [20090918-18:01:20.103586229] msec_range[15] 0.050000 - 0.100000 : 2 [20090918-18:01:20.107435774] msec_range[16] 0.020000 - 0.050000 : 149 [20090918-18:01:20.110956514] msec_range[17] 0.010000 - 0.020000 : 1612 [20090918-18:01:20.113458532] msec_range[18] 0.000000 - 0.010000 : 893 [20090918-18:01:20.116071213] [20090918-18:01:20.119331234] [20090918-18:01:20.122463132] [20090918-18:01:20.125583986] [20090918-18:01:20.129046137] 3.4% User Time [20090918-18:01:20.132145274] 54.4% System Time [20090918-18:01:20.135625077] 57.8% CPU Utilization [20090918-18:01:20.141559331] Profilers reporting [20090918-18:02:08.568201857] Profilers postprocessing [20090918-18:02:08.863627102] Processing File : iostat.001 [20090918-18:02:08.866155895] Discovered iostat_interval=[5] [20090918-18:02:09.699059123] Processing Directory : sar.breakout.001 [20090918-18:02:09.701361974] Discovered sar_interval=[5] [20090918-18:02:09.921457548] Processing File : mpstat.001 [20090918-18:02:09.924165080] Discovered mpstat_interval=[5] [20090918-18:02:11.074971952] Stopping profiling. [20090918-18:02:11.080917536] Killing daemon. [20090918-18:02:12.322162373] Processing File : oprofile.001 [20090918-18:02:12.324520679] Processing File : oprofile-brief.001 [20090918-18:02:15.748484581] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-09-18_1649/btrfsexp-9-18' [20090918-18:02:20.052595396] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090918-18:02:24.503955702] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090918-18:02:24.703225907] ONLY : Command [run random_writes__threads_0128 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb num_threads=128] found for me [20090918-18:02:24.756542941] PROCESSING COMMAND : 'run random_writes__threads_0128 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb num_threads=128' [20090918-18:02:24.805300526] new log requested [20090918-18:02:24.844708717] Running command ffsb [20090918-18:02:36.640232949] 09/18/2009-18:02:36 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb Succeeded [20090918-18:02:36.651940599] Importing argument : num_threads=128 [20090918-18:02:36.681389254] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090918-18:02:36.778485338] FFSB version 6.0-RC2.1 started [20090918-18:02:36.780547593] [20090918-18:02:37.321557933] benchmark time = 300 [20090918-18:02:37.323841608] ThreadGroup 0 [20090918-18:02:37.326073084] ================ [20090918-18:02:37.328329071] num_threads = 128 [20090918-18:02:37.330502879] [20090918-18:02:37.332836039] read_random = off [20090918-18:02:37.335001901] read_size = 0 (0B) [20090918-18:02:37.337137055] read_blocksize = 0 (0B) [20090918-18:02:37.339093853] read_skip = off [20090918-18:02:37.341084557] read_skipsize = 0 (0B) [20090918-18:02:37.343042651] [20090918-18:02:37.345053031] write_random = on [20090918-18:02:37.346978962] write_size = 5242880 (5MB) [20090918-18:02:37.348862759] fsync_file = 0 [20090918-18:02:37.350875163] write_blocksize = 4096 (4KB) [20090918-18:02:37.352794569] wait time = 0 [20090918-18:02:37.354850674] [20090918-18:02:37.356783148] op weights [20090918-18:02:37.358760186] read = 0 (0.00%) [20090918-18:02:37.360699118] readall = 0 (0.00%) [20090918-18:02:37.362714094] write = 1 (100.00%) [20090918-18:02:37.364677875] create = 0 (0.00%) [20090918-18:02:37.366675871] append = 0 (0.00%) [20090918-18:02:37.368564342] delete = 0 (0.00%) [20090918-18:02:37.370538279] metaop = 0 (0.00%) [20090918-18:02:37.372520557] createdir = 0 (0.00%) [20090918-18:02:37.374511407] stat = 0 (0.00%) [20090918-18:02:37.376399873] writeall = 0 (0.00%) [20090918-18:02:37.378370785] writeall_fsync = 0 (0.00%) [20090918-18:02:37.380302808] open_close = 0 (0.00%) [20090918-18:02:37.382307024] write_fsync = 0 (0.00%) [20090918-18:02:37.384196636] create_fsync = 0 (0.00%) [20090918-18:02:37.386163981] append_fsync = 0 (0.00%) [20090918-18:02:37.388109492] [20090918-18:02:37.390037847] FileSystem /mnt/ffsb1 [20090918-18:02:37.391943061] ========== [20090918-18:02:37.393850900] num_dirs = 0 [20090918-18:02:37.395934650] starting files = 1024 [20090918-18:02:37.397903239] [20090918-18:02:37.399913623] min file size = 104857600 (100MB) [20090918-18:02:37.401893873] max file size = 104857600 (100MB) [20090918-18:02:37.403793445] directio = off [20090918-18:02:37.405791596] alignedio = on [20090918-18:02:37.407776311] bufferedio = off [20090918-18:02:37.409803179] [20090918-18:02:37.411719209] aging is off [20090918-18:02:37.413720036] current utilization = 5.05% [20090918-18:02:37.415682461] [20090918-18:02:37.417684393] creating new fileset /mnt/ffsb1 [20090918-18:16:59.355749842] fs setup took 861 secs [20090918-18:17:17.447816469] Syncing()...18 sec [20090918-18:17:17.450506420] Starting Actual Benchmark At: Fri Sep 18 18:17:17 2009 [20090918-18:17:17.492892772] [20090918-18:22:44.527728761] Syncing()...15 sec [20090918-18:22:44.531022276] FFSB benchmark finished at: Fri Sep 18 18:22:44 2009 [20090918-18:22:44.534194824] [20090918-18:22:44.537444589] Results: [20090918-18:22:44.556901198] Benchmark took 326.88 sec [20090918-18:22:44.560070061] [20090918-18:22:44.562612105] Total Results [20090918-18:22:44.582072451] =============== [20090918-18:22:44.584897150] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090918-18:22:44.587905075] ======= ============ ========= ======= =========== ========== [20090918-18:22:44.590920243] write : 2910720 8904.46 100.000% 100.000% 34.8MB/sec [20090918-18:22:44.594301516] - [20090918-18:22:44.597043035] 8904.46 Transactions per Second [20090918-18:22:44.599756575] [20090918-18:22:44.603054548] Throughput Results [20090918-18:22:44.622760713] =================== [20090918-18:22:44.626216186] Write Throughput: 34.8MB/sec [20090918-18:22:44.629039264] [20090918-18:22:44.632058205] System Call Latency statistics in millisecs [20090918-18:22:44.636271174] ===== [20090918-18:22:44.640567136] Min Avg Max Total Calls [20090918-18:22:44.644104723] ======== ======== ======== ============ [20090918-18:22:44.647426389] [ open] 0.009000 2.025603 257.938995 2274 [20090918-18:22:44.652277173] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-18:22:44.655925492] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-18:22:44.658657655] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-18:22:44.661820025] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-18:22:44.664910607] msec_range[4] 200.000000 - 500.000000 : 8 [20090918-18:22:44.668505438] msec_range[5] 100.000000 - 200.000000 : 6 [20090918-18:22:44.671196916] msec_range[6] 50.000000 - 100.000000 : 17 [20090918-18:22:44.675299287] msec_range[7] 20.000000 - 50.000000 : 10 [20090918-18:22:44.678863301] msec_range[8] 10.000000 - 20.000000 : 7 [20090918-18:22:44.681813978] msec_range[9] 5.000000 - 10.000000 : 8 [20090918-18:22:44.684358072] msec_range[10] 2.000000 - 5.000000 : 9 [20090918-18:22:44.687598356] msec_range[11] 1.000000 - 2.000000 : 12 [20090918-18:22:44.690668881] msec_range[12] 0.500000 - 1.000000 : 13 [20090918-18:22:44.693474937] msec_range[13] 0.200000 - 0.500000 : 182 [20090918-18:22:44.696489832] msec_range[14] 0.100000 - 0.200000 : 593 [20090918-18:22:44.699568267] msec_range[15] 0.050000 - 0.100000 : 491 [20090918-18:22:44.702738960] msec_range[16] 0.020000 - 0.050000 : 855 [20090918-18:22:44.706204936] msec_range[17] 0.010000 - 0.020000 : 59 [20090918-18:22:44.709471885] msec_range[18] 0.000000 - 0.010000 : 4 [20090918-18:22:44.712937298] [20090918-18:22:44.716145763] [ write] 0.007000 12.926921 17132.972656 2910720 [20090918-18:22:44.719178017] msec_range[0] 5000.000000 - 10000.000000 : 720 [20090918-18:22:44.722147737] msec_range[1] 2000.000000 - 5000.000000 : 1880 [20090918-18:22:44.725161277] msec_range[2] 1000.000000 - 2000.000000 : 3517 [20090918-18:22:44.728101393] msec_range[3] 500.000000 - 1000.000000 : 8933 [20090918-18:22:44.731126042] msec_range[4] 200.000000 - 500.000000 : 18059 [20090918-18:22:44.734203835] msec_range[5] 100.000000 - 200.000000 : 14906 [20090918-18:22:44.737211299] msec_range[6] 50.000000 - 100.000000 : 12531 [20090918-18:22:44.740173079] msec_range[7] 20.000000 - 50.000000 : 14771 [20090918-18:22:44.743181748] msec_range[8] 10.000000 - 20.000000 : 7780 [20090918-18:22:44.746280377] msec_range[9] 5.000000 - 10.000000 : 8083 [20090918-18:22:44.749236828] msec_range[10] 2.000000 - 5.000000 : 9629 [20090918-18:22:44.752382990] msec_range[11] 1.000000 - 2.000000 : 6209 [20090918-18:22:44.755378190] msec_range[12] 0.500000 - 1.000000 : 7433 [20090918-18:22:44.758579575] msec_range[13] 0.200000 - 0.500000 : 85805 [20090918-18:22:44.761807356] msec_range[14] 0.100000 - 0.200000 : 375801 [20090918-18:22:44.770598545] msec_range[15] 0.050000 - 0.100000 : 852448 [20090918-18:22:44.774113536] msec_range[16] 0.020000 - 0.050000 : 1288507 [20090918-18:22:44.778655494] msec_range[17] 0.010000 - 0.020000 : 193199 [20090918-18:22:44.781993794] msec_range[18] 0.000000 - 0.010000 : 50 [20090918-18:22:44.791332057] [20090918-18:22:44.794994929] [ lseek] 0.000000 0.405929 16012.667969 2910720 [20090918-18:22:44.799794708] msec_range[0] 5000.000000 - 10000.000000 : 31 [20090918-18:22:44.805123286] msec_range[1] 2000.000000 - 5000.000000 : 81 [20090918-18:22:44.808973471] msec_range[2] 1000.000000 - 2000.000000 : 103 [20090918-18:22:44.813375094] msec_range[3] 500.000000 - 1000.000000 : 191 [20090918-18:22:44.817057289] msec_range[4] 200.000000 - 500.000000 : 290 [20090918-18:22:44.820357228] msec_range[5] 100.000000 - 200.000000 : 167 [20090918-18:22:44.838401743] msec_range[6] 50.000000 - 100.000000 : 188 [20090918-18:22:44.849613023] msec_range[7] 20.000000 - 50.000000 : 185 [20090918-18:22:44.866685834] msec_range[8] 10.000000 - 20.000000 : 108 [20090918-18:22:44.871363754] msec_range[9] 5.000000 - 10.000000 : 89 [20090918-18:22:44.879912739] msec_range[10] 2.000000 - 5.000000 : 60 [20090918-18:22:44.883400793] msec_range[11] 1.000000 - 2.000000 : 60 [20090918-18:22:44.887943924] msec_range[12] 0.500000 - 1.000000 : 56 [20090918-18:22:44.890949131] msec_range[13] 0.200000 - 0.500000 : 273 [20090918-18:22:44.894163518] msec_range[14] 0.100000 - 0.200000 : 2329 [20090918-18:22:44.897613027] msec_range[15] 0.050000 - 0.100000 : 9381 [20090918-18:22:44.905940477] msec_range[16] 0.020000 - 0.050000 : 24535 [20090918-18:22:44.911192304] msec_range[17] 0.010000 - 0.020000 : 28508 [20090918-18:22:44.922897694] msec_range[18] 0.000000 - 0.010000 : 2844064 [20090918-18:22:44.928532522] [20090918-18:22:44.933191048] [ close] 0.004000 0.012290 1.242000 2274 [20090918-18:22:44.936966626] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-18:22:44.941930173] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-18:22:44.945556448] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-18:22:44.948952862] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-18:22:44.952215911] msec_range[4] 200.000000 - 500.000000 : 0 [20090918-18:22:44.956098728] msec_range[5] 100.000000 - 200.000000 : 0 [20090918-18:22:44.959293644] msec_range[6] 50.000000 - 100.000000 : 0 [20090918-18:22:44.962121512] msec_range[7] 20.000000 - 50.000000 : 0 [20090918-18:22:44.965432990] msec_range[8] 10.000000 - 20.000000 : 0 [20090918-18:22:44.968688301] msec_range[9] 5.000000 - 10.000000 : 0 [20090918-18:22:44.971998125] msec_range[10] 2.000000 - 5.000000 : 0 [20090918-18:22:44.975625894] msec_range[11] 1.000000 - 2.000000 : 1 [20090918-18:22:44.979251185] msec_range[12] 0.500000 - 1.000000 : 0 [20090918-18:22:44.982254595] msec_range[13] 0.200000 - 0.500000 : 0 [20090918-18:22:44.985483334] msec_range[14] 0.100000 - 0.200000 : 1 [20090918-18:22:44.988578084] msec_range[15] 0.050000 - 0.100000 : 2 [20090918-18:22:44.992795429] msec_range[16] 0.020000 - 0.050000 : 108 [20090918-18:22:44.997393250] msec_range[17] 0.010000 - 0.020000 : 1388 [20090918-18:22:45.001276994] msec_range[18] 0.000000 - 0.010000 : 774 [20090918-18:22:45.007327635] [20090918-18:22:45.016597698] [20090918-18:22:45.019688939] [20090918-18:22:45.022966298] [20090918-18:22:45.026725435] 2.5% User Time [20090918-18:22:45.029699784] 282.6% System Time [20090918-18:22:45.034425489] 285.1% CPU Utilization [20090918-18:22:45.038606577] Profilers reporting [20090918-18:23:26.270142873] Profilers postprocessing [20090918-18:23:26.587870391] Processing File : iostat.001 [20090918-18:23:26.590174649] Discovered iostat_interval=[5] [20090918-18:23:27.464887318] Processing Directory : sar.breakout.001 [20090918-18:23:27.466961154] Discovered sar_interval=[5] [20090918-18:23:27.653055505] Processing File : mpstat.001 [20090918-18:23:27.655298404] Discovered mpstat_interval=[5] [20090918-18:23:28.804775166] Stopping profiling. [20090918-18:23:28.810208695] Killing daemon. [20090918-18:23:30.048480041] Processing File : oprofile.001 [20090918-18:23:30.050775577] Processing File : oprofile-brief.001 [20090918-18:23:33.219560301] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-09-18_1649/btrfsexp-9-18' [20090918-18:23:37.276972458] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090918-18:23:41.774814431] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090918-18:23:41.985291941] ONLY : Command [run random_writes_odirect__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb num_threads=1] found for me [20090918-18:23:42.038783146] PROCESSING COMMAND : 'run random_writes_odirect__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb num_threads=1' [20090918-18:23:42.087662367] new log requested [20090918-18:23:42.126884460] Running command ffsb [20090918-18:23:53.773332693] 09/18/2009-18:23:53 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb Succeeded [20090918-18:23:53.784783902] Importing argument : num_threads=1 [20090918-18:23:53.813086761] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090918-18:23:53.909595492] FFSB version 6.0-RC2.1 started [20090918-18:23:53.911952748] [20090918-18:23:53.914184988] benchmark time = 300 [20090918-18:23:53.916542669] ThreadGroup 0 [20090918-18:23:53.918817388] ================ [20090918-18:23:53.921130827] num_threads = 1 [20090918-18:23:53.923198006] [20090918-18:23:53.925472120] read_random = off [20090918-18:23:53.927546179] read_size = 0 (0B) [20090918-18:23:53.929543931] read_blocksize = 0 (0B) [20090918-18:23:53.931467369] read_skip = off [20090918-18:23:53.933465973] read_skipsize = 0 (0B) [20090918-18:23:53.935372156] [20090918-18:23:53.937338319] write_random = on [20090918-18:23:53.939342807] write_size = 5242880 (5MB) [20090918-18:23:53.941455933] fsync_file = 0 [20090918-18:23:53.943584537] write_blocksize = 4096 (4KB) [20090918-18:23:53.945523944] wait time = 0 [20090918-18:23:53.947599115] [20090918-18:23:53.949828993] op weights [20090918-18:23:53.951880009] read = 0 (0.00%) [20090918-18:23:53.953793270] readall = 0 (0.00%) [20090918-18:23:53.955818831] write = 1 (100.00%) [20090918-18:23:53.957760824] create = 0 (0.00%) [20090918-18:23:53.959742827] append = 0 (0.00%) [20090918-18:23:53.961651205] delete = 0 (0.00%) [20090918-18:23:53.963693034] metaop = 0 (0.00%) [20090918-18:23:53.965738411] createdir = 0 (0.00%) [20090918-18:23:53.967752641] stat = 0 (0.00%) [20090918-18:23:53.969644182] writeall = 0 (0.00%) [20090918-18:23:53.971685704] writeall_fsync = 0 (0.00%) [20090918-18:23:53.973591466] open_close = 0 (0.00%) [20090918-18:23:53.975537644] write_fsync = 0 (0.00%) [20090918-18:23:53.977437535] create_fsync = 0 (0.00%) [20090918-18:23:53.979429817] append_fsync = 0 (0.00%) [20090918-18:23:53.981444257] [20090918-18:23:53.983407682] FileSystem /mnt/ffsb1 [20090918-18:23:53.985310962] ========== [20090918-18:23:53.987294256] num_dirs = 0 [20090918-18:23:53.989405323] starting files = 1024 [20090918-18:23:53.991407811] [20090918-18:23:53.993287931] min file size = 104857600 (100MB) [20090918-18:23:53.995265510] max file size = 104857600 (100MB) [20090918-18:23:53.997431319] directio = on [20090918-18:23:53.999408891] alignedio = on [20090918-18:23:54.001298403] bufferedio = off [20090918-18:23:54.003272227] [20090918-18:23:54.005231505] aging is off [20090918-18:23:54.007385615] current utilization = 4.97% [20090918-18:23:54.009478852] [20090918-18:23:54.011589300] creating new fileset /mnt/ffsb1 [20090918-18:36:43.124118160] fs setup took 769 secs [20090918-18:37:05.508602986] Syncing()...22 sec [20090918-18:37:05.511041222] Starting Actual Benchmark At: Fri Sep 18 18:37:05 2009 [20090918-18:37:05.552256315] [20090918-18:42:08.689901717] Syncing()...1 sec [20090918-18:42:08.693759157] FFSB benchmark finished at: Fri Sep 18 18:42:08 2009 [20090918-18:42:08.697440230] [20090918-18:42:08.700724053] Results: [20090918-18:42:08.722671087] Benchmark took 303.18 sec [20090918-18:42:08.726162408] [20090918-18:42:08.729139812] Total Results [20090918-18:42:08.749381068] =============== [20090918-18:42:08.754150915] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090918-18:42:08.758758121] ======= ============ ========= ======= =========== ========== [20090918-18:42:08.762254837] write : 634880 2094.07 100.000% 100.000% 8.18MB/sec [20090918-18:42:08.765395602] - [20090918-18:42:08.768489224] 2094.07 Transactions per Second [20090918-18:42:08.772426904] [20090918-18:42:08.776403239] Throughput Results [20090918-18:42:08.796319364] =================== [20090918-18:42:08.799642466] Write Throughput: 8.18MB/sec [20090918-18:42:08.803003656] [20090918-18:42:08.806431824] System Call Latency statistics in millisecs [20090918-18:42:08.809506942] ===== [20090918-18:42:08.818614643] Min Avg Max Total Calls [20090918-18:42:08.837507098] ======== ======== ======== ============ [20090918-18:42:08.840965719] [ open] 0.011000 0.030149 0.208000 496 [20090918-18:42:08.844651729] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-18:42:08.847985800] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-18:42:08.851990678] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-18:42:08.856964872] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-18:42:08.860704635] msec_range[4] 200.000000 - 500.000000 : 0 [20090918-18:42:08.864231794] msec_range[5] 100.000000 - 200.000000 : 0 [20090918-18:42:08.867415419] msec_range[6] 50.000000 - 100.000000 : 0 [20090918-18:42:08.870753258] msec_range[7] 20.000000 - 50.000000 : 0 [20090918-18:42:08.876620585] msec_range[8] 10.000000 - 20.000000 : 0 [20090918-18:42:08.886956233] msec_range[9] 5.000000 - 10.000000 : 0 [20090918-18:42:08.893285820] msec_range[10] 2.000000 - 5.000000 : 0 [20090918-18:42:08.897523924] msec_range[11] 1.000000 - 2.000000 : 0 [20090918-18:42:08.903890555] msec_range[12] 0.500000 - 1.000000 : 0 [20090918-18:42:08.907752203] msec_range[13] 0.200000 - 0.500000 : 1 [20090918-18:42:08.911425411] msec_range[14] 0.100000 - 0.200000 : 6 [20090918-18:42:08.914902806] msec_range[15] 0.050000 - 0.100000 : 53 [20090918-18:42:08.932928308] msec_range[16] 0.020000 - 0.050000 : 338 [20090918-18:42:08.944862866] msec_range[17] 0.010000 - 0.020000 : 98 [20090918-18:42:08.949196581] msec_range[18] 0.000000 - 0.010000 : 0 [20090918-18:42:08.951929821] [20090918-18:42:08.955038163] [ write] 0.320000 0.471880 313.446991 634880 [20090918-18:42:08.958166372] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-18:42:08.961845450] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-18:42:08.965142701] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-18:42:08.968013511] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-18:42:08.971212235] msec_range[4] 200.000000 - 500.000000 : 9 [20090918-18:42:08.974605226] msec_range[5] 100.000000 - 200.000000 : 0 [20090918-18:42:08.978181363] msec_range[6] 50.000000 - 100.000000 : 2 [20090918-18:42:08.981816888] msec_range[7] 20.000000 - 50.000000 : 9 [20090918-18:42:08.985223309] msec_range[8] 10.000000 - 20.000000 : 18 [20090918-18:42:08.988182793] msec_range[9] 5.000000 - 10.000000 : 91 [20090918-18:42:08.991704360] msec_range[10] 2.000000 - 5.000000 : 2108 [20090918-18:42:09.002377168] msec_range[11] 1.000000 - 2.000000 : 2425 [20090918-18:42:09.007018100] msec_range[12] 0.500000 - 1.000000 : 101896 [20090918-18:42:09.011410431] msec_range[13] 0.200000 - 0.500000 : 528322 [20090918-18:42:09.015259507] msec_range[14] 0.100000 - 0.200000 : 0 [20090918-18:42:09.018854841] msec_range[15] 0.050000 - 0.100000 : 0 [20090918-18:42:09.023298201] msec_range[16] 0.020000 - 0.050000 : 0 [20090918-18:42:09.028201711] msec_range[17] 0.010000 - 0.020000 : 0 [20090918-18:42:09.031868786] msec_range[18] 0.000000 - 0.010000 : 0 [20090918-18:42:09.037253041] [20090918-18:42:09.066581290] [ lseek] 0.000000 0.001372 4.030000 634880 [20090918-18:42:09.070940067] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-18:42:09.075009542] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-18:42:09.079008228] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-18:42:09.082984973] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-18:42:09.087036026] msec_range[4] 200.000000 - 500.000000 : 0 [20090918-18:42:09.092630806] msec_range[5] 100.000000 - 200.000000 : 0 [20090918-18:42:09.095997695] msec_range[6] 50.000000 - 100.000000 : 0 [20090918-18:42:09.100800587] msec_range[7] 20.000000 - 50.000000 : 0 [20090918-18:42:09.105466845] msec_range[8] 10.000000 - 20.000000 : 0 [20090918-18:42:09.109615789] msec_range[9] 5.000000 - 10.000000 : 0 [20090918-18:42:09.114055781] msec_range[10] 2.000000 - 5.000000 : 5 [20090918-18:42:09.122224921] msec_range[11] 1.000000 - 2.000000 : 0 [20090918-18:42:09.126760653] msec_range[12] 0.500000 - 1.000000 : 0 [20090918-18:42:09.135562708] msec_range[13] 0.200000 - 0.500000 : 0 [20090918-18:42:09.140257882] msec_range[14] 0.100000 - 0.200000 : 3 [20090918-18:42:09.143379046] msec_range[15] 0.050000 - 0.100000 : 1 [20090918-18:42:09.148378696] msec_range[16] 0.020000 - 0.050000 : 4 [20090918-18:42:09.151819946] msec_range[17] 0.010000 - 0.020000 : 243 [20090918-18:42:09.155248413] msec_range[18] 0.000000 - 0.010000 : 634624 [20090918-18:42:09.159686383] [20090918-18:42:09.168807251] [ close] 0.003000 0.006232 0.018000 496 [20090918-18:42:09.174646980] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-18:42:09.178258456] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-18:42:09.181006629] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-18:42:09.184346339] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-18:42:09.187705927] msec_range[4] 200.000000 - 500.000000 : 0 [20090918-18:42:09.190607624] msec_range[5] 100.000000 - 200.000000 : 0 [20090918-18:42:09.194182748] msec_range[6] 50.000000 - 100.000000 : 0 [20090918-18:42:09.198252171] msec_range[7] 20.000000 - 50.000000 : 0 [20090918-18:42:09.201260994] msec_range[8] 10.000000 - 20.000000 : 0 [20090918-18:42:09.204757625] msec_range[9] 5.000000 - 10.000000 : 0 [20090918-18:42:09.207610904] msec_range[10] 2.000000 - 5.000000 : 0 [20090918-18:42:09.216656412] msec_range[11] 1.000000 - 2.000000 : 0 [20090918-18:42:09.219455731] msec_range[12] 0.500000 - 1.000000 : 0 [20090918-18:42:09.222280558] msec_range[13] 0.200000 - 0.500000 : 0 [20090918-18:42:09.225127401] msec_range[14] 0.100000 - 0.200000 : 0 [20090918-18:42:09.228940986] msec_range[15] 0.050000 - 0.100000 : 0 [20090918-18:42:09.231721365] msec_range[16] 0.020000 - 0.050000 : 0 [20090918-18:42:09.234582231] msec_range[17] 0.010000 - 0.020000 : 34 [20090918-18:42:09.237343899] msec_range[18] 0.000000 - 0.010000 : 462 [20090918-18:42:09.240362949] [20090918-18:42:09.243141506] [20090918-18:42:09.245953632] [20090918-18:42:09.248723393] [20090918-18:42:09.251429346] 0.5% User Time [20090918-18:42:09.255476356] 16.4% System Time [20090918-18:42:09.258297040] 16.9% CPU Utilization [20090918-18:42:09.261025800] Profilers reporting [20090918-18:42:37.337200121] Profilers postprocessing [20090918-18:42:37.655704468] Processing File : iostat.001 [20090918-18:42:37.658088875] Discovered iostat_interval=[5] [20090918-18:42:38.958255843] Processing Directory : sar.breakout.001 [20090918-18:42:38.960707344] Discovered sar_interval=[5] [20090918-18:42:39.157778920] Processing File : mpstat.001 [20090918-18:42:39.160305901] Discovered mpstat_interval=[5] [20090918-18:42:40.309257401] Stopping profiling. [20090918-18:42:40.316854314] Killing daemon. [20090918-18:42:41.578374783] Processing File : oprofile.001 [20090918-18:42:41.580839206] Processing File : oprofile-brief.001 [20090918-18:42:45.127040947] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-09-18_1649/btrfsexp-9-18' [20090918-18:42:48.945119662] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090918-18:42:51.823335764] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090918-18:42:52.006039293] ONLY : Command [run random_writes_odirect__threads_0016 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb num_threads=16] found for me [20090918-18:42:52.058850738] PROCESSING COMMAND : 'run random_writes_odirect__threads_0016 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb num_threads=16' [20090918-18:42:52.108476959] new log requested [20090918-18:42:52.150662855] Running command ffsb [20090918-18:43:03.756942617] 09/18/2009-18:43:03 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb Succeeded [20090918-18:43:03.768141955] Importing argument : num_threads=16 [20090918-18:43:03.796817026] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090918-18:43:03.896086213] FFSB version 6.0-RC2.1 started [20090918-18:43:03.898369080] [20090918-18:43:03.962695588] benchmark time = 300 [20090918-18:43:03.964948503] ThreadGroup 0 [20090918-18:43:03.967202767] ================ [20090918-18:43:03.969328002] num_threads = 16 [20090918-18:43:03.971502339] [20090918-18:43:03.973737156] read_random = off [20090918-18:43:03.975894185] read_size = 0 (0B) [20090918-18:43:03.978182328] read_blocksize = 0 (0B) [20090918-18:43:03.980247955] read_skip = off [20090918-18:43:03.982239982] read_skipsize = 0 (0B) [20090918-18:43:03.984159124] [20090918-18:43:03.986145479] write_random = on [20090918-18:43:03.988064931] write_size = 5242880 (5MB) [20090918-18:43:03.990020383] fsync_file = 0 [20090918-18:43:03.991911961] write_blocksize = 4096 (4KB) [20090918-18:43:03.993916244] wait time = 0 [20090918-18:43:03.995859457] [20090918-18:43:03.997819187] op weights [20090918-18:43:03.999723289] read = 0 (0.00%) [20090918-18:43:04.001797295] readall = 0 (0.00%) [20090918-18:43:04.003710719] write = 1 (100.00%) [20090918-18:43:04.005648734] create = 0 (0.00%) [20090918-18:43:04.007526107] append = 0 (0.00%) [20090918-18:43:04.009721511] delete = 0 (0.00%) [20090918-18:43:04.011873286] metaop = 0 (0.00%) [20090918-18:43:04.013821790] createdir = 0 (0.00%) [20090918-18:43:04.016004197] stat = 0 (0.00%) [20090918-18:43:04.018060238] writeall = 0 (0.00%) [20090918-18:43:04.019952334] writeall_fsync = 0 (0.00%) [20090918-18:43:04.022099946] open_close = 0 (0.00%) [20090918-18:43:04.024181523] write_fsync = 0 (0.00%) [20090918-18:43:04.026199709] create_fsync = 0 (0.00%) [20090918-18:43:04.028113426] append_fsync = 0 (0.00%) [20090918-18:43:04.030420458] [20090918-18:43:04.032564336] FileSystem /mnt/ffsb1 [20090918-18:43:04.034493713] ========== [20090918-18:43:04.036549119] num_dirs = 0 [20090918-18:43:04.038524760] starting files = 1024 [20090918-18:43:04.040530875] [20090918-18:43:04.042419970] min file size = 104857600 (100MB) [20090918-18:43:04.044430215] max file size = 104857600 (100MB) [20090918-18:43:04.046394339] directio = on [20090918-18:43:04.048383812] alignedio = on [20090918-18:43:04.050263384] bufferedio = off [20090918-18:43:04.052239414] [20090918-18:43:04.054148486] aging is off [20090918-18:43:04.056462998] current utilization = 4.59% [20090918-18:43:04.058358946] [20090918-18:43:04.060332327] creating new fileset /mnt/ffsb1 [20090918-18:48:20.188629030] fs setup took 316 secs [20090918-18:48:45.266241820] Syncing()...25 sec [20090918-18:48:45.269606375] Starting Actual Benchmark At: Fri Sep 18 18:48:45 2009 [20090918-18:48:45.303061023] [20090918-18:53:51.141309996] Syncing()...3 sec [20090918-18:53:51.144950677] FFSB benchmark finished at: Fri Sep 18 18:53:51 2009 [20090918-18:53:51.148648303] [20090918-18:53:51.152259888] Results: [20090918-18:53:51.172273038] Benchmark took 305.87 sec [20090918-18:53:51.175391234] [20090918-18:53:51.178756230] Total Results [20090918-18:53:51.203468751] =============== [20090918-18:53:51.206829458] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090918-18:53:51.209914261] ======= ============ ========= ======= =========== ========== [20090918-18:53:51.212626597] write : 2304000 7532.64 100.000% 100.000% 29.4MB/sec [20090918-18:53:51.216060780] - [20090918-18:53:51.220817063] 7532.64 Transactions per Second [20090918-18:53:51.223659378] [20090918-18:53:51.230467347] Throughput Results [20090918-18:53:51.251157892] =================== [20090918-18:53:51.254838355] Write Throughput: 29.4MB/sec [20090918-18:53:51.258411211] [20090918-18:53:51.262483233] System Call Latency statistics in millisecs [20090918-18:53:51.267768235] ===== [20090918-18:53:51.276319153] Min Avg Max Total Calls [20090918-18:53:51.280901833] ======== ======== ======== ============ [20090918-18:53:51.285055138] [ open] 0.008000 0.058024 1.125000 1800 [20090918-18:53:51.289868450] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-18:53:51.293491452] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-18:53:51.297158005] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-18:53:51.301536431] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-18:53:51.304747777] msec_range[4] 200.000000 - 500.000000 : 0 [20090918-18:53:51.308555297] msec_range[5] 100.000000 - 200.000000 : 0 [20090918-18:53:51.311952567] msec_range[6] 50.000000 - 100.000000 : 0 [20090918-18:53:51.316557412] msec_range[7] 20.000000 - 50.000000 : 0 [20090918-18:53:51.320691937] msec_range[8] 10.000000 - 20.000000 : 0 [20090918-18:53:51.323761888] msec_range[9] 5.000000 - 10.000000 : 0 [20090918-18:53:51.326973405] msec_range[10] 2.000000 - 5.000000 : 0 [20090918-18:53:51.331374479] msec_range[11] 1.000000 - 2.000000 : 1 [20090918-18:53:51.335469867] msec_range[12] 0.500000 - 1.000000 : 1 [20090918-18:53:51.341152407] msec_range[13] 0.200000 - 0.500000 : 57 [20090918-18:53:51.345073693] msec_range[14] 0.100000 - 0.200000 : 223 [20090918-18:53:51.355903398] msec_range[15] 0.050000 - 0.100000 : 222 [20090918-18:53:51.359397018] msec_range[16] 0.020000 - 0.050000 : 1245 [20090918-18:53:51.362408624] msec_range[17] 0.010000 - 0.020000 : 44 [20090918-18:53:51.366438095] msec_range[18] 0.000000 - 0.010000 : 7 [20090918-18:53:51.369098753] [20090918-18:53:51.371887848] [ write] 0.354000 2.091739 561.302979 2304000 [20090918-18:53:51.380193395] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-18:53:51.383949270] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-18:53:51.390208163] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-18:53:51.395365542] msec_range[3] 500.000000 - 1000.000000 : 32 [20090918-18:53:51.400079946] msec_range[4] 200.000000 - 500.000000 : 186 [20090918-18:53:51.402861748] msec_range[5] 100.000000 - 200.000000 : 326 [20090918-18:53:51.406063210] msec_range[6] 50.000000 - 100.000000 : 1906 [20090918-18:53:51.409232278] msec_range[7] 20.000000 - 50.000000 : 3547 [20090918-18:53:51.412703755] msec_range[8] 10.000000 - 20.000000 : 11064 [20090918-18:53:51.416217007] msec_range[9] 5.000000 - 10.000000 : 81209 [20090918-18:53:51.420300926] msec_range[10] 2.000000 - 5.000000 : 573062 [20090918-18:53:51.424072217] msec_range[11] 1.000000 - 2.000000 : 1324691 [20090918-18:53:51.426902990] msec_range[12] 0.500000 - 1.000000 : 306334 [20090918-18:53:51.430105260] msec_range[13] 0.200000 - 0.500000 : 1643 [20090918-18:53:51.435247354] msec_range[14] 0.100000 - 0.200000 : 0 [20090918-18:53:51.439499432] msec_range[15] 0.050000 - 0.100000 : 0 [20090918-18:53:51.443656660] msec_range[16] 0.020000 - 0.050000 : 0 [20090918-18:53:51.447080395] msec_range[17] 0.010000 - 0.020000 : 0 [20090918-18:53:51.450612411] msec_range[18] 0.000000 - 0.010000 : 0 [20090918-18:53:51.455518937] [20090918-18:53:51.458995563] [ lseek] 0.000000 0.002397 38.835999 2304000 [20090918-18:53:51.462163150] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-18:53:51.468892049] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-18:53:51.473329064] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-18:53:51.477125765] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-18:53:51.492377907] msec_range[4] 200.000000 - 500.000000 : 0 [20090918-18:53:51.499361637] msec_range[5] 100.000000 - 200.000000 : 0 [20090918-18:53:51.505280279] msec_range[6] 50.000000 - 100.000000 : 0 [20090918-18:53:51.509609926] msec_range[7] 20.000000 - 50.000000 : 1 [20090918-18:53:51.513615857] msec_range[8] 10.000000 - 20.000000 : 1 [20090918-18:53:51.517559426] msec_range[9] 5.000000 - 10.000000 : 16 [20090918-18:53:51.521588567] msec_range[10] 2.000000 - 5.000000 : 25 [20090918-18:53:51.525341149] msec_range[11] 1.000000 - 2.000000 : 59 [20090918-18:53:51.530976429] msec_range[12] 0.500000 - 1.000000 : 168 [20090918-18:53:51.535786027] msec_range[13] 0.200000 - 0.500000 : 692 [20090918-18:53:51.539351329] msec_range[14] 0.100000 - 0.200000 : 1060 [20090918-18:53:51.543309421] msec_range[15] 0.050000 - 0.100000 : 1364 [20090918-18:53:51.547056110] msec_range[16] 0.020000 - 0.050000 : 3727 [20090918-18:53:51.550874382] msec_range[17] 0.010000 - 0.020000 : 13200 [20090918-18:53:51.554197127] msec_range[18] 0.000000 - 0.010000 : 2283687 [20090918-18:53:51.558160151] [20090918-18:53:51.560792370] [ close] 0.003000 0.009683 0.229000 1800 [20090918-18:53:51.563860598] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090918-18:53:51.567890743] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090918-18:53:51.571833877] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090918-18:53:51.576525870] msec_range[3] 500.000000 - 1000.000000 : 0 [20090918-18:53:51.580510366] msec_range[4] 200.000000 - 500.000000 : 0 [20090918-18:53:51.583897478] msec_range[5] 100.000000 - 200.000000 : 0 [20090918-18:53:51.586924891] msec_range[6] 50.000000 - 100.000000 : 0 [20090918-18:53:51.592713773] msec_range[7] 20.000000 - 50.000000 : 0 [20090918-18:53:51.595856124] msec_range[8] 10.000000 - 20.000000 : 0 [20090918-18:53:51.600001667] msec_range[9] 5.000000 - 10.000000 : 0 [20090918-18:53:51.603077157] msec_range[10] 2.000000 - 5.000000 : 0 [20090918-18:53:51.606239443] msec_range[11] 1.000000 - 2.000000 : 0 [20090918-18:53:51.609102822] msec_range[12] 0.500000 - 1.000000 : 0 [20090918-18:53:51.611836911] msec_range[13] 0.200000 - 0.500000 : 1 [20090918-18:53:51.614542311] msec_range[14] 0.100000 - 0.200000 : 0 [20090918-18:53:51.617246458] msec_range[15] 0.050000 - 0.100000 : 1 [20090918-18:53:51.620131098] msec_range[16] 0.020000 - 0.050000 : 27 [20090918-18:53:51.622814405] msec_range[17] 0.010000 - 0.020000 : 578 [20090918-18:53:51.626066174] msec_range[18] 0.000000 - 0.010000 : 1193 [20090918-18:53:51.629461767] [20090918-18:53:51.632389558] [20090918-18:53:51.635388425] [20090918-18:53:51.638468862] [20090918-18:53:51.641428261] 2.7% User Time [20090918-18:53:51.643998534] 154.6% System Time [20090918-18:53:51.647256687] 157.3% CPU Utilization [20090918-18:53:51.650360407] Profilers reporting [20090918-18:54:32.835521051] Profilers postprocessing [20090918-18:54:33.065210356] Processing File : iostat.001 [20090918-18:54:33.067647723] Discovered iostat_interval=[5] [20090918-18:54:33.828619226] Processing Directory : sar.breakout.001 [20090918-18:54:33.831140483] Discovered sar_interval=[5] [20090918-18:54:34.004261019] Processing File : mpstat.001 [20090918-18:54:34.006617171] Discovered mpstat_interval=[5] [20090918-18:54:35.152709928] Stopping profiling. [20090918-18:54:35.160574849] Killing daemon. [20090918-18:54:36.423876578] Processing File : oprofile.001 [20090918-18:54:36.426188689] Processing File : oprofile-brief.001 [20090918-18:54:39.055554584] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-09-18_1649/btrfsexp-9-18'