[20091015-09:53:02.600071996] PROCESSING COMMAND : 'clearprofilers' [20091015-09:53:02.894864422] PROCESSING COMMAND : 'useprofiler iostat 5' [20091015-09:53:03.015284862] Checking for sar... [20091015-09:53:03.017372811] found [20091015-09:53:03.167108366] PROCESSING COMMAND : 'useprofiler sar 5' [20091015-09:53:03.289048085] Checking for sar... [20091015-09:53:03.291543781] found [20091015-09:53:03.440671831] PROCESSING COMMAND : 'useprofiler mpstat 5' [20091015-09:53:03.561059497] Checking for sar... [20091015-09:53:03.563175318] found [20091015-09:53:03.746864456] PROCESSING COMMAND : 'useprofiler oprofile' [20091015-09:53:03.937106993] Checking for gettext... [20091015-09:53:03.947225673] found [20091015-09:53:03.948964558] Checking for libiberty in autobench... [20091015-09:53:03.984762419] found [20091015-09:53:03.993470331] Checking for popt64... [20091015-09:53:03.995269151] found [20091015-09:53:03.996999160] Checking for oprofile... [20091015-09:53:04.018665727] found [20091015-09:53:04.090005298] opcontrol: oprofile 0.9.5-rc2 compiled on Oct 2 2009 16:03:29 [20091015-09:53:04.330328163] Daemon not running [20091015-09:53:20.419184858] OPROFILE : using callgraph [5] [20091015-09:53:20.667940988] Daemon not running [20091015-09:53:20.670547001] Separate options: none [20091015-09:53:20.672756478] vmlinux file: /boot/vmlinux-2.6.31-autokern1 [20091015-09:53:20.674606622] Image filter: none [20091015-09:53:20.676532043] Call-graph depth: 5 [20091015-09:53:20.897181493] PROCESSING COMMAND : 'umount /mnt/ffsb1 > /dev/null 2>&1' [20091015-09:53:20.980775675] PROCESSING COMMAND : 'set-sched noop' [20091015-09:53:21.314593033] PROCESSING COMMAND : 'mkresultdirs hks.austin.ibm.com benchmarks/results/btrfs/ffsb btrfs1 2009-10-15_0953 btrfs10-15' [20091015-09:53:21.551372025] Connecting to hks.austin.ibm.com... [20091015-09:53:21.553477104] Remote working directory: /opt [20091015-09:53:21.557295605] Remote working directory: /opt/benchmarks/results/btrfs/ffsb [20091015-09:53:21.559179087] Couldn't create directory: Failure [20091015-09:53:21.561119300] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1 [20091015-09:53:21.562932251] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs1 [20091015-09:53:21.564696995] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1/2009-10-15_0953 [20091015-09:53:21.566497009] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs1/2009-10-15_0953 [20091015-09:53:21.568342137] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1/2009-10-15_0953/btrfs10-15 [20091015-09:53:21.630696259] ONLY : Command [mkfs.btrfs 2>&1] found for me [20091015-09:53:21.681491725] PROCESSING COMMAND : 'mkfs.btrfs 2>&1' [20091015-09:53:21.709698572] usage: mkfs.btrfs [options] dev [ dev ... ] [20091015-09:53:21.711537887] options: [20091015-09:53:21.714883544] -A --alloc-start the offset to start the FS [20091015-09:53:21.716878147] -b --byte-count total number of bytes in the FS [20091015-09:53:21.718728684] -d --data data profile, raid0, raid1, raid10 or single [20091015-09:53:21.720560990] -l --leafsize size of btree leaves [20091015-09:53:21.722308022] -L --label set a label [20091015-09:53:21.724073341] -m --metadata metadata profile, values like data profile [20091015-09:53:21.725878042] -n --nodesize size of btree nodes [20091015-09:53:21.727623077] -s --sectorsize min block allocation [20091015-09:53:21.729378421] Btrfs v0.18-13-gb8420fa [20091015-09:53:21.812175971] PROCESSING COMMAND : 'mkfs.btrfs /dev/ffsbdev1' [20091015-09:53:21.848098322] [20091015-09:53:21.850169443] WARNING! - Btrfs v0.18-13-gb8420fa IS EXPERIMENTAL [20091015-09:53:21.851965553] WARNING! - see http://btrfs.wiki.kernel.org before using [20091015-09:53:21.853717570] [20091015-09:53:21.855418391] fs created label (null) on /dev/ffsbdev1 [20091015-09:53:21.857239598] nodesize 4096 leafsize 4096 sectorsize 4096 size 2.18TB [20091015-09:53:21.859658342] Btrfs v0.18-13-gb8420fa [20091015-09:53:22.031134747] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20091015-09:53:22.315738654] 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 [20091015-09:53:22.368304876] 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' [20091015-09:53:22.425973485] new log requested [20091015-09:53:22.459695301] Running command ffsb [20091015-09:53:35.308585136] 10/15/2009-09:53:35 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb Succeeded [20091015-09:53:35.319636275] Importing argument : reuse=1 [20091015-09:53:35.332734245] Importing argument : num_threads=1 [20091015-09:53:35.363345251] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20091015-09:53:35.474809767] FFSB version 6.0-RC2.1 started [20091015-09:53:35.476693271] [20091015-09:53:35.478578167] benchmark time = 300 [20091015-09:53:35.480331098] ThreadGroup 0 [20091015-09:53:35.482202338] ================ [20091015-09:53:35.484003434] num_threads = 1 [20091015-09:53:35.485892262] [20091015-09:53:35.487677202] read_random = off [20091015-09:53:35.489478130] read_size = 0 (0B) [20091015-09:53:35.491282562] read_blocksize = 4096 (4KB) [20091015-09:53:35.493273261] read_skip = off [20091015-09:53:35.495111788] read_skipsize = 0 (0B) [20091015-09:53:35.496902566] [20091015-09:53:35.498656831] write_random = off [20091015-09:53:35.500436000] write_size = 0 (0B) [20091015-09:53:35.502201229] fsync_file = 0 [20091015-09:53:35.503946048] write_blocksize = 0 (0B) [20091015-09:53:35.505728668] wait time = 0 [20091015-09:53:35.507494829] [20091015-09:53:35.509276996] op weights [20091015-09:53:35.511049387] read = 0 (0.00%) [20091015-09:53:35.512784780] readall = 1 (100.00%) [20091015-09:53:35.514541759] write = 0 (0.00%) [20091015-09:53:35.516272582] create = 0 (0.00%) [20091015-09:53:35.518021376] append = 0 (0.00%) [20091015-09:53:35.520419634] delete = 0 (0.00%) [20091015-09:53:35.522802791] metaop = 0 (0.00%) [20091015-09:53:35.524886093] createdir = 0 (0.00%) [20091015-09:53:35.527193149] stat = 0 (0.00%) [20091015-09:53:35.529597904] writeall = 0 (0.00%) [20091015-09:53:35.531532203] writeall_fsync = 0 (0.00%) [20091015-09:53:35.533942152] open_close = 0 (0.00%) [20091015-09:53:35.536122068] write_fsync = 0 (0.00%) [20091015-09:53:35.538303904] create_fsync = 0 (0.00%) [20091015-09:53:35.540264567] append_fsync = 0 (0.00%) [20091015-09:53:35.542352610] [20091015-09:53:35.544351865] FileSystem /mnt/ffsb1 [20091015-09:53:35.546246442] ========== [20091015-09:53:35.548308832] num_dirs = 0 [20091015-09:53:35.550294060] starting files = 1024 [20091015-09:53:35.552202561] [20091015-09:53:35.554126790] min file size = 104857600 (100MB) [20091015-09:53:35.556040383] max file size = 104857600 (100MB) [20091015-09:53:35.558126835] directio = off [20091015-09:53:35.560213367] alignedio = on [20091015-09:53:35.562099654] bufferedio = off [20091015-09:53:35.564183690] [20091015-09:53:35.566217964] aging is off [20091015-09:53:35.568124547] current utilization = 0.00% [20091015-09:53:35.570164852] [20091015-09:53:35.572202629] checking existing fs: /mnt/ffsb1 [20091015-09:53:35.574114627] opendir: No such file or directory [20091015-09:53:35.576180022] recreating new fileset [20091015-09:57:40.828529996] fs setup took 245 secs [20091015-09:58:19.346028353] Syncing()...38 sec [20091015-09:58:19.348698808] Starting Actual Benchmark At: Thu Oct 15 09:58:19 2009 [20091015-09:58:19.382244161] [20091015-10:03:22.916235020] Syncing()...2 sec [20091015-10:03:22.948856315] FFSB benchmark finished at: Thu Oct 15 10:03:22 2009 [20091015-10:03:22.952238093] [20091015-10:03:22.955678242] Results: [20091015-10:03:22.998106103] Benchmark took 303.12 sec [20091015-10:03:23.000998133] [20091015-10:03:23.003943944] Total Results [20091015-10:03:23.023898277] =============== [20091015-10:03:23.027210800] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20091015-10:03:23.030520550] ======= ============ ========= ======= =========== ========== [20091015-10:03:23.033350374] readall : 19814400 65368.19 100.000% 100.000% 255MB/sec [20091015-10:03:23.036348977] - [20091015-10:03:23.039062463] 65368.19 Transactions per Second [20091015-10:03:23.042007427] [20091015-10:03:23.045117783] Throughput Results [20091015-10:03:23.064510424] =================== [20091015-10:03:23.068433655] Read Throughput: 255MB/sec [20091015-10:03:23.072316889] [20091015-10:03:23.075397212] System Call Latency statistics in millisecs [20091015-10:03:23.078461643] ===== [20091015-10:03:23.081846145] Min Avg Max Total Calls [20091015-10:03:23.084730830] ======== ======== ======== ============ [20091015-10:03:23.087529643] [ open] 0.022000 0.143819 6.400000 774 [20091015-10:03:23.090535357] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-10:03:23.093275005] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-10:03:23.095850943] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-10:03:23.098524634] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-10:03:23.101374153] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-10:03:23.104365812] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-10:03:23.108087473] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-10:03:23.110833283] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-10:03:23.113545504] msec_range[8] 10.000000 - 20.000000 : 0 [20091015-10:03:23.116160475] msec_range[9] 5.000000 - 10.000000 : 3 [20091015-10:03:23.119546220] msec_range[10] 2.000000 - 5.000000 : 10 [20091015-10:03:23.122433508] msec_range[11] 1.000000 - 2.000000 : 0 [20091015-10:03:23.125269826] msec_range[12] 0.500000 - 1.000000 : 0 [20091015-10:03:23.128252135] msec_range[13] 0.200000 - 0.500000 : 4 [20091015-10:03:23.131688245] msec_range[14] 0.100000 - 0.200000 : 90 [20091015-10:03:23.134822303] msec_range[15] 0.050000 - 0.100000 : 536 [20091015-10:03:23.137358953] msec_range[16] 0.020000 - 0.050000 : 131 [20091015-10:03:23.140072834] msec_range[17] 0.010000 - 0.020000 : 0 [20091015-10:03:23.142853759] msec_range[18] 0.000000 - 0.010000 : 0 [20091015-10:03:23.145638217] [20091015-10:03:23.149411705] [ read] 0.001000 0.014931 78.347000 19814400 [20091015-10:03:23.154212515] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-10:03:23.157746700] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-10:03:23.161236841] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-10:03:23.164243187] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-10:03:23.167276839] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-10:03:23.170480519] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-10:03:23.173721850] msec_range[6] 50.000000 - 100.000000 : 1 [20091015-10:03:23.176586721] msec_range[7] 20.000000 - 50.000000 : 55 [20091015-10:03:23.179403638] msec_range[8] 10.000000 - 20.000000 : 3303 [20091015-10:03:23.182034323] msec_range[9] 5.000000 - 10.000000 : 14450 [20091015-10:03:23.184764179] msec_range[10] 2.000000 - 5.000000 : 6045 [20091015-10:03:23.187503260] msec_range[11] 1.000000 - 2.000000 : 2165 [20091015-10:03:23.192062448] msec_range[12] 0.500000 - 1.000000 : 3542 [20091015-10:03:23.195054359] msec_range[13] 0.200000 - 0.500000 : 3062 [20091015-10:03:23.200922452] msec_range[14] 0.100000 - 0.200000 : 3636 [20091015-10:03:23.204357145] msec_range[15] 0.050000 - 0.100000 : 14986 [20091015-10:03:23.207370745] msec_range[16] 0.020000 - 0.050000 : 32780 [20091015-10:03:23.210281947] msec_range[17] 0.010000 - 0.020000 : 779380 [20091015-10:03:23.213043623] msec_range[18] 0.000000 - 0.010000 : 18950995 [20091015-10:03:23.215873827] [20091015-10:03:23.218553161] [ close] 0.006000 0.009249 0.029000 774 [20091015-10:03:23.221223356] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-10:03:23.224140993] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-10:03:23.227517617] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-10:03:23.230130323] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-10:03:23.232821570] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-10:03:23.235684845] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-10:03:23.238592257] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-10:03:23.241153865] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-10:03:23.243905064] msec_range[8] 10.000000 - 20.000000 : 0 [20091015-10:03:23.247264342] msec_range[9] 5.000000 - 10.000000 : 0 [20091015-10:03:23.250680441] msec_range[10] 2.000000 - 5.000000 : 0 [20091015-10:03:23.255280490] msec_range[11] 1.000000 - 2.000000 : 0 [20091015-10:03:23.258442696] msec_range[12] 0.500000 - 1.000000 : 0 [20091015-10:03:23.261558487] msec_range[13] 0.200000 - 0.500000 : 0 [20091015-10:03:23.265103102] msec_range[14] 0.100000 - 0.200000 : 0 [20091015-10:03:23.267989830] msec_range[15] 0.050000 - 0.100000 : 0 [20091015-10:03:23.271090980] msec_range[16] 0.020000 - 0.050000 : 1 [20091015-10:03:23.274374792] msec_range[17] 0.010000 - 0.020000 : 176 [20091015-10:03:23.277309147] msec_range[18] 0.000000 - 0.010000 : 597 [20091015-10:03:23.280275419] [20091015-10:03:23.283005185] [20091015-10:03:23.286097434] [20091015-10:03:23.290718026] [20091015-10:03:23.294040600] 3.6% User Time [20091015-10:03:23.297240291] 80.5% System Time [20091015-10:03:23.299964399] 84.1% CPU Utilization [20091015-10:03:23.302832446] Profilers reporting [20091015-10:03:57.022826179] Profilers postprocessing [20091015-10:03:57.323078730] Processing File : iostat.001 [20091015-10:03:57.325375136] Discovered iostat_interval=[5] [20091015-10:03:58.106099514] Processing Directory : sar.breakout.001 [20091015-10:03:58.108301372] Discovered sar_interval=[5] [20091015-10:03:58.286199265] Processing File : mpstat.001 [20091015-10:03:58.288582531] Discovered mpstat_interval=[5] [20091015-10:03:59.434064131] Stopping profiling. [20091015-10:03:59.439883788] Killing daemon. [20091015-10:04:01.752261524] Processing File : oprofile.001 [20091015-10:04:01.754510227] Processing File : oprofile-brief.001 [20091015-10:04:03.379455666] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-10-15_0953/btrfs10-15' [20091015-10:04:07.430843744] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20091015-10:04:10.118137469] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20091015-10:04:10.589471685] 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 [20091015-10:04:10.643079117] 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' [20091015-10:04:10.691555234] new log requested [20091015-10:04:10.734757514] Running command ffsb [20091015-10:04:22.202793927] 10/15/2009-10:04:22 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb Succeeded [20091015-10:04:22.213742657] Importing argument : reuse=1 [20091015-10:04:22.227282397] Importing argument : num_threads=16 [20091015-10:04:22.255643315] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20091015-10:04:22.341030044] FFSB version 6.0-RC2.1 started [20091015-10:04:22.343333863] [20091015-10:04:22.408997394] benchmark time = 300 [20091015-10:04:22.411170215] ThreadGroup 0 [20091015-10:04:22.413177735] ================ [20091015-10:04:22.415095033] num_threads = 16 [20091015-10:04:22.417075778] [20091015-10:04:22.419017034] read_random = off [20091015-10:04:22.421030441] read_size = 0 (0B) [20091015-10:04:22.422935518] read_blocksize = 4096 (4KB) [20091015-10:04:22.424861800] read_skip = off [20091015-10:04:22.426855042] read_skipsize = 0 (0B) [20091015-10:04:22.428798192] [20091015-10:04:22.430688093] write_random = off [20091015-10:04:22.432646892] write_size = 0 (0B) [20091015-10:04:22.434524480] fsync_file = 0 [20091015-10:04:22.436466483] write_blocksize = 0 (0B) [20091015-10:04:22.438329807] wait time = 0 [20091015-10:04:22.440277606] [20091015-10:04:22.442165636] op weights [20091015-10:04:22.444141857] read = 0 (0.00%) [20091015-10:04:22.446055085] readall = 1 (100.00%) [20091015-10:04:22.447981808] write = 0 (0.00%) [20091015-10:04:22.449889470] create = 0 (0.00%) [20091015-10:04:22.451816514] append = 0 (0.00%) [20091015-10:04:22.453697130] delete = 0 (0.00%) [20091015-10:04:22.455665710] metaop = 0 (0.00%) [20091015-10:04:22.457559022] createdir = 0 (0.00%) [20091015-10:04:22.459515539] stat = 0 (0.00%) [20091015-10:04:22.461381231] writeall = 0 (0.00%) [20091015-10:04:22.463295289] writeall_fsync = 0 (0.00%) [20091015-10:04:22.465192192] open_close = 0 (0.00%) [20091015-10:04:22.467181431] write_fsync = 0 (0.00%) [20091015-10:04:22.469084282] create_fsync = 0 (0.00%) [20091015-10:04:22.471056794] append_fsync = 0 (0.00%) [20091015-10:04:22.472948829] [20091015-10:04:22.474886089] FileSystem /mnt/ffsb1 [20091015-10:04:22.476747814] ========== [20091015-10:04:22.478654061] num_dirs = 0 [20091015-10:04:22.480589570] starting files = 1024 [20091015-10:04:22.482472957] [20091015-10:04:22.484374770] min file size = 104857600 (100MB) [20091015-10:04:22.486307342] max file size = 104857600 (100MB) [20091015-10:04:22.488207435] directio = off [20091015-10:04:22.490162525] alignedio = on [20091015-10:04:22.492051868] bufferedio = off [20091015-10:04:22.493965254] [20091015-10:04:22.495814560] aging is off [20091015-10:04:22.497720477] current utilization = 4.48% [20091015-10:04:22.499597005] [20091015-10:04:22.501568657] checking existing fs: /mnt/ffsb1 [20091015-10:04:23.430348798] fs setup took 1 secs [20091015-10:04:24.374005154] Syncing()...0 sec [20091015-10:04:24.379182781] Starting Actual Benchmark At: Thu Oct 15 10:04:24 2009 [20091015-10:04:24.397809294] [20091015-10:09:27.909536051] Syncing()...0 sec [20091015-10:09:27.929338946] FFSB benchmark finished at: Thu Oct 15 10:09:27 2009 [20091015-10:09:27.932723828] [20091015-10:09:27.936271039] Results: [20091015-10:09:27.996819724] Benchmark took 303.03 sec [20091015-10:09:28.000208356] [20091015-10:09:28.003691451] Total Results [20091015-10:09:28.023845091] =============== [20091015-10:09:28.027014325] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20091015-10:09:28.030108279] ======= ============ ========= ======= =========== ========== [20091015-10:09:28.033471758] readall : 37657600 124269.05 100.000% 100.000% 485MB/sec [20091015-10:09:28.036645109] - [20091015-10:09:28.040208126] 124269.05 Transactions per Second [20091015-10:09:28.043390558] [20091015-10:09:28.047120345] Throughput Results [20091015-10:09:28.067557065] =================== [20091015-10:09:28.070124484] Read Throughput: 485MB/sec [20091015-10:09:28.072985250] [20091015-10:09:28.076424085] System Call Latency statistics in millisecs [20091015-10:09:28.079264976] ===== [20091015-10:09:28.082355684] Min Avg Max Total Calls [20091015-10:09:28.085592701] ======== ======== ======== ============ [20091015-10:09:28.088517900] [ open] 0.007000 1.964310 278.480011 1471 [20091015-10:09:28.091295477] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-10:09:28.094097354] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-10:09:28.096900008] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-10:09:28.099657128] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-10:09:28.102288167] msec_range[4] 200.000000 - 500.000000 : 4 [20091015-10:09:28.105056346] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-10:09:28.107727515] msec_range[6] 50.000000 - 100.000000 : 6 [20091015-10:09:28.110498496] msec_range[7] 20.000000 - 50.000000 : 16 [20091015-10:09:28.113161980] msec_range[8] 10.000000 - 20.000000 : 39 [20091015-10:09:28.115973991] msec_range[9] 5.000000 - 10.000000 : 32 [20091015-10:09:28.119082439] msec_range[10] 2.000000 - 5.000000 : 16 [20091015-10:09:28.122752041] msec_range[11] 1.000000 - 2.000000 : 1 [20091015-10:09:28.125891199] msec_range[12] 0.500000 - 1.000000 : 1 [20091015-10:09:28.128990187] msec_range[13] 0.200000 - 0.500000 : 14 [20091015-10:09:28.132033498] msec_range[14] 0.100000 - 0.200000 : 360 [20091015-10:09:28.134909236] msec_range[15] 0.050000 - 0.100000 : 643 [20091015-10:09:28.137710790] msec_range[16] 0.020000 - 0.050000 : 317 [20091015-10:09:28.140856842] msec_range[17] 0.010000 - 0.020000 : 12 [20091015-10:09:28.143835393] msec_range[18] 0.000000 - 0.010000 : 10 [20091015-10:09:28.146651968] [20091015-10:09:28.149506399] [ read] 0.001000 0.127736 4038.185059 37657600 [20091015-10:09:28.152466150] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-10:09:28.155299463] msec_range[1] 2000.000000 - 5000.000000 : 22 [20091015-10:09:28.158175708] msec_range[2] 1000.000000 - 2000.000000 : 97 [20091015-10:09:28.161259031] msec_range[3] 500.000000 - 1000.000000 : 81 [20091015-10:09:28.164300784] msec_range[4] 200.000000 - 500.000000 : 1706 [20091015-10:09:28.168225980] msec_range[5] 100.000000 - 200.000000 : 12479 [20091015-10:09:28.170997995] msec_range[6] 50.000000 - 100.000000 : 13842 [20091015-10:09:28.173760136] msec_range[7] 20.000000 - 50.000000 : 18569 [20091015-10:09:28.176544299] msec_range[8] 10.000000 - 20.000000 : 16811 [20091015-10:09:28.179921525] msec_range[9] 5.000000 - 10.000000 : 25899 [20091015-10:09:28.182801575] msec_range[10] 2.000000 - 5.000000 : 20673 [20091015-10:09:28.185480202] msec_range[11] 1.000000 - 2.000000 : 22914 [20091015-10:09:28.188250234] msec_range[12] 0.500000 - 1.000000 : 7263 [20091015-10:09:28.191342712] msec_range[13] 0.200000 - 0.500000 : 6198 [20091015-10:09:28.194499501] msec_range[14] 0.100000 - 0.200000 : 5255 [20091015-10:09:28.197183337] msec_range[15] 0.050000 - 0.100000 : 14087 [20091015-10:09:28.200977620] msec_range[16] 0.020000 - 0.050000 : 372982 [20091015-10:09:28.206548036] msec_range[17] 0.010000 - 0.020000 : 3264022 [20091015-10:09:28.209940007] msec_range[18] 0.000000 - 0.010000 : 33854700 [20091015-10:09:28.213181410] [20091015-10:09:28.216636041] [ close] 0.003000 0.010332 0.065000 1471 [20091015-10:09:28.219984946] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-10:09:28.223458866] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-10:09:28.226940615] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-10:09:28.230133093] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-10:09:28.233100147] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-10:09:28.235911541] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-10:09:28.238719075] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-10:09:28.241636582] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-10:09:28.244506775] msec_range[8] 10.000000 - 20.000000 : 0 [20091015-10:09:28.247155642] msec_range[9] 5.000000 - 10.000000 : 0 [20091015-10:09:28.249790167] msec_range[10] 2.000000 - 5.000000 : 0 [20091015-10:09:28.252428759] msec_range[11] 1.000000 - 2.000000 : 0 [20091015-10:09:28.255628518] msec_range[12] 0.500000 - 1.000000 : 0 [20091015-10:09:28.258459055] msec_range[13] 0.200000 - 0.500000 : 0 [20091015-10:09:28.261538403] msec_range[14] 0.100000 - 0.200000 : 0 [20091015-10:09:28.264415013] msec_range[15] 0.050000 - 0.100000 : 1 [20091015-10:09:28.267358179] msec_range[16] 0.020000 - 0.050000 : 16 [20091015-10:09:28.270209688] msec_range[17] 0.010000 - 0.020000 : 745 [20091015-10:09:28.273180959] msec_range[18] 0.000000 - 0.010000 : 709 [20091015-10:09:28.275959248] [20091015-10:09:28.278917723] [20091015-10:09:28.281707617] [20091015-10:09:28.284404592] [20091015-10:09:28.288894854] 8.7% User Time [20091015-10:09:28.291774255] 170.5% System Time [20091015-10:09:28.294608141] 179.2% CPU Utilization [20091015-10:09:28.303938717] Profilers reporting [20091015-10:10:08.651975453] Profilers postprocessing [20091015-10:10:08.963759016] Processing File : iostat.001 [20091015-10:10:08.966076583] Discovered iostat_interval=[5] [20091015-10:10:09.755380961] Processing Directory : sar.breakout.001 [20091015-10:10:09.757564033] Discovered sar_interval=[5] [20091015-10:10:09.929528310] Processing File : mpstat.001 [20091015-10:10:09.931700910] Discovered mpstat_interval=[5] [20091015-10:10:11.081173085] Stopping profiling. [20091015-10:10:11.086812010] Killing daemon. [20091015-10:10:12.409032625] Processing File : oprofile.001 [20091015-10:10:12.411366944] Processing File : oprofile-brief.001 [20091015-10:10:14.027489262] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-10-15_0953/btrfs10-15' [20091015-10:10:18.435506146] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20091015-10:10:21.220186116] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20091015-10:10:21.660447083] 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 [20091015-10:10:21.714570646] 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' [20091015-10:10:21.763274175] new log requested [20091015-10:10:21.794010655] Running command ffsb [20091015-10:10:33.399893398] 10/15/2009-10:10:33 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb Succeeded [20091015-10:10:33.411692468] Importing argument : reuse=1 [20091015-10:10:33.425385573] Importing argument : num_threads=128 [20091015-10:10:33.455210380] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20091015-10:10:33.544167289] FFSB version 6.0-RC2.1 started [20091015-10:10:33.546647535] [20091015-10:10:34.091975555] benchmark time = 300 [20091015-10:10:34.094007240] ThreadGroup 0 [20091015-10:10:34.095882966] ================ [20091015-10:10:34.098097420] num_threads = 128 [20091015-10:10:34.100271542] [20091015-10:10:34.102149732] read_random = off [20091015-10:10:34.104124596] read_size = 0 (0B) [20091015-10:10:34.106113914] read_blocksize = 4096 (4KB) [20091015-10:10:34.108151228] read_skip = off [20091015-10:10:34.110039238] read_skipsize = 0 (0B) [20091015-10:10:34.111995059] [20091015-10:10:34.113900319] write_random = off [20091015-10:10:34.116232601] write_size = 0 (0B) [20091015-10:10:34.118539305] fsync_file = 0 [20091015-10:10:34.120856427] write_blocksize = 0 (0B) [20091015-10:10:34.122896955] wait time = 0 [20091015-10:10:34.124921356] [20091015-10:10:34.126856856] op weights [20091015-10:10:34.128850031] read = 0 (0.00%) [20091015-10:10:34.130772577] readall = 1 (100.00%) [20091015-10:10:34.132746124] write = 0 (0.00%) [20091015-10:10:34.134657898] create = 0 (0.00%) [20091015-10:10:34.136623812] append = 0 (0.00%) [20091015-10:10:34.138531102] delete = 0 (0.00%) [20091015-10:10:34.140518309] metaop = 0 (0.00%) [20091015-10:10:34.142449810] createdir = 0 (0.00%) [20091015-10:10:34.144405443] stat = 0 (0.00%) [20091015-10:10:34.146416612] writeall = 0 (0.00%) [20091015-10:10:34.148376050] writeall_fsync = 0 (0.00%) [20091015-10:10:34.150260889] open_close = 0 (0.00%) [20091015-10:10:34.152148842] write_fsync = 0 (0.00%) [20091015-10:10:34.154036959] create_fsync = 0 (0.00%) [20091015-10:10:34.156033885] append_fsync = 0 (0.00%) [20091015-10:10:34.157923349] [20091015-10:10:34.159851088] FileSystem /mnt/ffsb1 [20091015-10:10:34.161711770] ========== [20091015-10:10:34.163685923] num_dirs = 0 [20091015-10:10:34.165551746] starting files = 1024 [20091015-10:10:34.167509805] [20091015-10:10:34.169389634] min file size = 104857600 (100MB) [20091015-10:10:34.171332116] max file size = 104857600 (100MB) [20091015-10:10:34.173225731] directio = off [20091015-10:10:34.175240249] alignedio = on [20091015-10:10:34.177161135] bufferedio = off [20091015-10:10:34.179164611] [20091015-10:10:34.181035715] aging is off [20091015-10:10:34.183006915] current utilization = 4.48% [20091015-10:10:34.184885588] [20091015-10:10:34.186850281] checking existing fs: /mnt/ffsb1 [20091015-10:10:34.634159099] fs setup took 0 secs [20091015-10:10:36.112553100] Syncing()...1 sec [20091015-10:10:36.117842384] Starting Actual Benchmark At: Thu Oct 15 10:10:36 2009 [20091015-10:10:36.138212150] [20091015-10:15:53.175091645] Syncing()...2 sec [20091015-10:15:53.209410821] FFSB benchmark finished at: Thu Oct 15 10:15:52 2009 [20091015-10:15:53.212352847] [20091015-10:15:53.215822489] Results: [20091015-10:15:53.262154198] Benchmark took 316.59 sec [20091015-10:15:53.265024947] [20091015-10:15:53.268319295] Total Results [20091015-10:15:53.286933537] =============== [20091015-10:15:53.289227418] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20091015-10:15:53.292000497] ======= ============ ========= ======= =========== ========== [20091015-10:15:53.295143089] readall : 33689600 106414.06 100.000% 100.000% 416MB/sec [20091015-10:15:53.297787948] - [20091015-10:15:53.300865728] 106414.06 Transactions per Second [20091015-10:15:53.304082990] [20091015-10:15:53.307145024] Throughput Results [20091015-10:15:53.326549389] =================== [20091015-10:15:53.329284903] Read Throughput: 416MB/sec [20091015-10:15:53.331676066] [20091015-10:15:53.334675725] System Call Latency statistics in millisecs [20091015-10:15:53.337795522] ===== [20091015-10:15:53.340300919] Min Avg Max Total Calls [20091015-10:15:53.343215151] ======== ======== ======== ============ [20091015-10:15:53.346152689] [ open] 0.007000 55.401717 6259.912109 1316 [20091015-10:15:53.349492285] msec_range[0] 5000.000000 - 10000.000000 : 5 [20091015-10:15:53.351752993] msec_range[1] 2000.000000 - 5000.000000 : 4 [20091015-10:15:53.354624487] msec_range[2] 1000.000000 - 2000.000000 : 15 [20091015-10:15:53.357308185] msec_range[3] 500.000000 - 1000.000000 : 5 [20091015-10:15:53.359967979] msec_range[4] 200.000000 - 500.000000 : 7 [20091015-10:15:53.362977609] msec_range[5] 100.000000 - 200.000000 : 12 [20091015-10:15:53.366104246] msec_range[6] 50.000000 - 100.000000 : 10 [20091015-10:15:53.368634729] msec_range[7] 20.000000 - 50.000000 : 28 [20091015-10:15:53.370986589] msec_range[8] 10.000000 - 20.000000 : 24 [20091015-10:15:53.373969803] msec_range[9] 5.000000 - 10.000000 : 22 [20091015-10:15:53.376775786] msec_range[10] 2.000000 - 5.000000 : 11 [20091015-10:15:53.379278364] msec_range[11] 1.000000 - 2.000000 : 2 [20091015-10:15:53.382181627] msec_range[12] 0.500000 - 1.000000 : 1 [20091015-10:15:53.385051105] msec_range[13] 0.200000 - 0.500000 : 15 [20091015-10:15:53.387742132] msec_range[14] 0.100000 - 0.200000 : 399 [20091015-10:15:53.390237896] msec_range[15] 0.050000 - 0.100000 : 334 [20091015-10:15:53.392467232] msec_range[16] 0.020000 - 0.050000 : 294 [20091015-10:15:53.395175923] msec_range[17] 0.010000 - 0.020000 : 88 [20091015-10:15:53.397849731] msec_range[18] 0.000000 - 0.010000 : 40 [20091015-10:15:53.400257149] [20091015-10:15:53.402433346] [ read] 0.001000 1.174299 57848.902344 33689600 [20091015-10:15:53.405075336] msec_range[0] 5000.000000 - 10000.000000 : 91 [20091015-10:15:53.407725141] msec_range[1] 2000.000000 - 5000.000000 : 4145 [20091015-10:15:53.410266785] msec_range[2] 1000.000000 - 2000.000000 : 7800 [20091015-10:15:53.412610281] msec_range[3] 500.000000 - 1000.000000 : 11321 [20091015-10:15:53.415661979] msec_range[4] 200.000000 - 500.000000 : 15016 [20091015-10:15:53.418250219] msec_range[5] 100.000000 - 200.000000 : 8884 [20091015-10:15:53.420501294] msec_range[6] 50.000000 - 100.000000 : 7945 [20091015-10:15:53.423312436] msec_range[7] 20.000000 - 50.000000 : 10766 [20091015-10:15:53.426143653] msec_range[8] 10.000000 - 20.000000 : 11546 [20091015-10:15:53.430210566] msec_range[9] 5.000000 - 10.000000 : 18789 [20091015-10:15:53.433083789] msec_range[10] 2.000000 - 5.000000 : 16064 [20091015-10:15:53.435936170] msec_range[11] 1.000000 - 2.000000 : 17802 [20091015-10:15:53.438645658] msec_range[12] 0.500000 - 1.000000 : 12604 [20091015-10:15:53.441182435] msec_range[13] 0.200000 - 0.500000 : 6439 [20091015-10:15:53.443691885] msec_range[14] 0.100000 - 0.200000 : 6242 [20091015-10:15:53.446522497] msec_range[15] 0.050000 - 0.100000 : 11977 [20091015-10:15:53.449082036] msec_range[16] 0.020000 - 0.050000 : 460300 [20091015-10:15:53.451334400] msec_range[17] 0.010000 - 0.020000 : 4027859 [20091015-10:15:53.454374490] msec_range[18] 0.000000 - 0.010000 : 29033935 [20091015-10:15:53.457828282] [20091015-10:15:53.461497516] [ close] 0.004000 0.058694 18.737000 1316 [20091015-10:15:53.464629069] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-10:15:53.468002759] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-10:15:53.470457392] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-10:15:53.473390706] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-10:15:53.476544584] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-10:15:53.479022479] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-10:15:53.481218274] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-10:15:53.483939357] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-10:15:53.486707563] msec_range[8] 10.000000 - 20.000000 : 2 [20091015-10:15:53.489606982] msec_range[9] 5.000000 - 10.000000 : 3 [20091015-10:15:53.492375172] msec_range[10] 2.000000 - 5.000000 : 2 [20091015-10:15:53.495842303] msec_range[11] 1.000000 - 2.000000 : 1 [20091015-10:15:53.498909315] msec_range[12] 0.500000 - 1.000000 : 2 [20091015-10:15:53.501555427] msec_range[13] 0.200000 - 0.500000 : 5 [20091015-10:15:53.504112932] msec_range[14] 0.100000 - 0.200000 : 1 [20091015-10:15:53.506350132] msec_range[15] 0.050000 - 0.100000 : 4 [20091015-10:15:53.509086845] msec_range[16] 0.020000 - 0.050000 : 38 [20091015-10:15:53.511724811] msec_range[17] 0.010000 - 0.020000 : 790 [20091015-10:15:53.514215641] msec_range[18] 0.000000 - 0.010000 : 468 [20091015-10:15:53.516702913] [20091015-10:15:53.520138373] [20091015-10:15:53.522904174] [20091015-10:15:53.525349400] [20091015-10:15:53.528444804] 8.1% User Time [20091015-10:15:53.532256392] 169.9% System Time [20091015-10:15:53.534886621] 178.0% CPU Utilization [20091015-10:15:53.543254372] Profilers reporting [20091015-10:16:34.520344109] Profilers postprocessing [20091015-10:16:34.831708388] Processing File : iostat.001 [20091015-10:16:34.834106127] Discovered iostat_interval=[5] [20091015-10:16:35.623934232] Processing Directory : sar.breakout.001 [20091015-10:16:35.626066773] Discovered sar_interval=[5] [20091015-10:16:35.837652780] Processing File : mpstat.001 [20091015-10:16:35.839889235] Discovered mpstat_interval=[5] [20091015-10:16:36.986885887] Stopping profiling. [20091015-10:16:36.992383332] Killing daemon. [20091015-10:16:38.292773887] Processing File : oprofile.001 [20091015-10:16:38.295019342] Processing File : oprofile-brief.001 [20091015-10:16:40.119864333] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-10-15_0953/btrfs10-15' [20091015-10:16:44.316974920] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20091015-10:16:47.001526452] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20091015-10:16:47.455141703] 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 [20091015-10:16:47.508379888] 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' [20091015-10:16:47.556613500] new log requested [20091015-10:16:47.587597405] Running command ffsb [20091015-10:16:59.520696629] 10/15/2009-10:16:59 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb Succeeded [20091015-10:16:59.531923047] Importing argument : reuse=1 [20091015-10:16:59.545553192] Importing argument : num_threads=1 [20091015-10:16:59.574479699] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20091015-10:16:59.661176614] FFSB version 6.0-RC2.1 started [20091015-10:16:59.663112508] [20091015-10:16:59.665485104] benchmark time = 300 [20091015-10:16:59.667949421] ThreadGroup 0 [20091015-10:16:59.670176334] ================ [20091015-10:16:59.672548022] num_threads = 1 [20091015-10:16:59.674660954] [20091015-10:16:59.676680127] read_random = on [20091015-10:16:59.678586445] read_size = 5242880 (5MB) [20091015-10:16:59.680575377] read_blocksize = 4096 (4KB) [20091015-10:16:59.682522574] read_skip = off [20091015-10:16:59.684502226] read_skipsize = 0 (0B) [20091015-10:16:59.686386591] [20091015-10:16:59.688345373] write_random = off [20091015-10:16:59.690312748] write_size = 0 (0B) [20091015-10:16:59.692336118] fsync_file = 0 [20091015-10:16:59.694223327] write_blocksize = 0 (0B) [20091015-10:16:59.696184048] wait time = 0 [20091015-10:16:59.698115011] [20091015-10:16:59.700014713] op weights [20091015-10:16:59.701925954] read = 1 (100.00%) [20091015-10:16:59.703882585] readall = 0 (0.00%) [20091015-10:16:59.705837298] write = 0 (0.00%) [20091015-10:16:59.707845637] create = 0 (0.00%) [20091015-10:16:59.709716837] append = 0 (0.00%) [20091015-10:16:59.711657979] delete = 0 (0.00%) [20091015-10:16:59.713597251] metaop = 0 (0.00%) [20091015-10:16:59.715584936] createdir = 0 (0.00%) [20091015-10:16:59.717459638] stat = 0 (0.00%) [20091015-10:16:59.719402408] writeall = 0 (0.00%) [20091015-10:16:59.721334326] writeall_fsync = 0 (0.00%) [20091015-10:16:59.723317617] open_close = 0 (0.00%) [20091015-10:16:59.725190537] write_fsync = 0 (0.00%) [20091015-10:16:59.727104218] create_fsync = 0 (0.00%) [20091015-10:16:59.729036612] append_fsync = 0 (0.00%) [20091015-10:16:59.731066526] [20091015-10:16:59.732960973] FileSystem /mnt/ffsb1 [20091015-10:16:59.734928310] ========== [20091015-10:16:59.736909229] num_dirs = 0 [20091015-10:16:59.738904645] starting files = 1024 [20091015-10:16:59.740775215] [20091015-10:16:59.742729284] min file size = 104857600 (100MB) [20091015-10:16:59.744719217] max file size = 104857600 (100MB) [20091015-10:16:59.746691859] directio = off [20091015-10:16:59.748571426] alignedio = on [20091015-10:16:59.750525890] bufferedio = off [20091015-10:16:59.752585070] [20091015-10:16:59.754761061] aging is off [20091015-10:16:59.756749136] current utilization = 4.48% [20091015-10:16:59.758986718] [20091015-10:16:59.761088328] checking existing fs: /mnt/ffsb1 [20091015-10:17:00.216279832] fs setup took 0 secs [20091015-10:17:01.478017050] Syncing()...1 sec [20091015-10:17:01.480465810] Starting Actual Benchmark At: Thu Oct 15 10:17:01 2009 [20091015-10:17:01.496258290] [20091015-10:22:06.781412360] Syncing()...2 sec [20091015-10:22:06.785057871] FFSB benchmark finished at: Thu Oct 15 10:22:06 2009 [20091015-10:22:06.788424662] [20091015-10:22:06.792936144] Results: [20091015-10:22:06.814796068] Benchmark took 305.30 sec [20091015-10:22:06.818066507] [20091015-10:22:06.822073954] Total Results [20091015-10:22:06.839095651] =============== [20091015-10:22:06.842713399] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20091015-10:22:06.845957844] ======= ============ ========= ======= =========== ========== [20091015-10:22:06.849243839] read : 165120 540.84 100.000% 100.000% 2.11MB/sec [20091015-10:22:06.852223038] - [20091015-10:22:06.855006994] 540.84 Transactions per Second [20091015-10:22:06.871281533] [20091015-10:22:06.875180631] Throughput Results [20091015-10:22:06.897727163] =================== [20091015-10:22:06.901142803] Read Throughput: 2.11MB/sec [20091015-10:22:06.905230244] [20091015-10:22:06.915987308] System Call Latency statistics in millisecs [20091015-10:22:06.928059912] ===== [20091015-10:22:06.934517688] Min Avg Max Total Calls [20091015-10:22:06.940189707] ======== ======== ======== ============ [20091015-10:22:06.944417269] [ open] 0.014000 0.029101 0.043000 129 [20091015-10:22:06.949186753] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-10:22:06.952846572] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-10:22:06.960147367] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-10:22:06.965313246] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-10:22:06.969224459] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-10:22:06.973522706] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-10:22:06.977580147] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-10:22:06.980732576] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-10:22:06.984890738] msec_range[8] 10.000000 - 20.000000 : 0 [20091015-10:22:06.988298525] msec_range[9] 5.000000 - 10.000000 : 0 [20091015-10:22:06.992172064] msec_range[10] 2.000000 - 5.000000 : 0 [20091015-10:22:06.996568743] msec_range[11] 1.000000 - 2.000000 : 0 [20091015-10:22:07.000180990] msec_range[12] 0.500000 - 1.000000 : 0 [20091015-10:22:07.004375024] msec_range[13] 0.200000 - 0.500000 : 0 [20091015-10:22:07.007897196] msec_range[14] 0.100000 - 0.200000 : 0 [20091015-10:22:07.034077438] msec_range[15] 0.050000 - 0.100000 : 0 [20091015-10:22:07.038042511] msec_range[16] 0.020000 - 0.050000 : 121 [20091015-10:22:07.041200263] msec_range[17] 0.010000 - 0.020000 : 8 [20091015-10:22:07.044479186] msec_range[18] 0.000000 - 0.010000 : 0 [20091015-10:22:07.047820714] [20091015-10:22:07.050897541] [ read] 0.002000 1.832147 40.759998 165120 [20091015-10:22:07.054310191] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-10:22:07.057721855] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-10:22:07.060944419] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-10:22:07.064170735] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-10:22:07.067462159] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-10:22:07.070704466] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-10:22:07.074200719] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-10:22:07.078504139] msec_range[7] 20.000000 - 50.000000 : 87 [20091015-10:22:07.083842812] msec_range[8] 10.000000 - 20.000000 : 1029 [20091015-10:22:07.088545608] msec_range[9] 5.000000 - 10.000000 : 13678 [20091015-10:22:07.091494020] msec_range[10] 2.000000 - 5.000000 : 40483 [20091015-10:22:07.096288317] msec_range[11] 1.000000 - 2.000000 : 10345 [20091015-10:22:07.099658045] msec_range[12] 0.500000 - 1.000000 : 2809 [20091015-10:22:07.103215615] msec_range[13] 0.200000 - 0.500000 : 87614 [20091015-10:22:07.106232929] msec_range[14] 0.100000 - 0.200000 : 199 [20091015-10:22:07.110242305] msec_range[15] 0.050000 - 0.100000 : 1 [20091015-10:22:07.113127813] msec_range[16] 0.020000 - 0.050000 : 36 [20091015-10:22:07.116386463] msec_range[17] 0.010000 - 0.020000 : 1483 [20091015-10:22:07.129620432] msec_range[18] 0.000000 - 0.010000 : 7356 [20091015-10:22:07.136397674] [20091015-10:22:07.159730346] [ lseek] 0.000000 0.001276 1.639000 165120 [20091015-10:22:07.163380506] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-10:22:07.166810976] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-10:22:07.170268673] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-10:22:07.173681396] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-10:22:07.176997690] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-10:22:07.180309552] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-10:22:07.183242880] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-10:22:07.186303975] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-10:22:07.189403099] msec_range[8] 10.000000 - 20.000000 : 0 [20091015-10:22:07.192910189] msec_range[9] 5.000000 - 10.000000 : 0 [20091015-10:22:07.196219611] msec_range[10] 2.000000 - 5.000000 : 0 [20091015-10:22:07.200543721] msec_range[11] 1.000000 - 2.000000 : 1 [20091015-10:22:07.204558971] msec_range[12] 0.500000 - 1.000000 : 0 [20091015-10:22:07.211202966] msec_range[13] 0.200000 - 0.500000 : 0 [20091015-10:22:07.215358998] msec_range[14] 0.100000 - 0.200000 : 0 [20091015-10:22:07.218535367] msec_range[15] 0.050000 - 0.100000 : 0 [20091015-10:22:07.222264741] msec_range[16] 0.020000 - 0.050000 : 1 [20091015-10:22:07.225524498] msec_range[17] 0.010000 - 0.020000 : 152 [20091015-10:22:07.234484114] msec_range[18] 0.000000 - 0.010000 : 164966 [20091015-10:22:07.238353601] [20091015-10:22:07.241436284] [ close] 0.004000 0.007705 0.015000 129 [20091015-10:22:07.244045393] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-10:22:07.246658233] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-10:22:07.250579685] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-10:22:07.253022497] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-10:22:07.257426044] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-10:22:07.260265553] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-10:22:07.263375782] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-10:22:07.266336707] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-10:22:07.269097485] msec_range[8] 10.000000 - 20.000000 : 0 [20091015-10:22:07.271934144] msec_range[9] 5.000000 - 10.000000 : 0 [20091015-10:22:07.274716775] msec_range[10] 2.000000 - 5.000000 : 0 [20091015-10:22:07.277369734] msec_range[11] 1.000000 - 2.000000 : 0 [20091015-10:22:07.280080790] msec_range[12] 0.500000 - 1.000000 : 0 [20091015-10:22:07.282876811] msec_range[13] 0.200000 - 0.500000 : 0 [20091015-10:22:07.285624550] msec_range[14] 0.100000 - 0.200000 : 0 [20091015-10:22:07.288465148] msec_range[15] 0.050000 - 0.100000 : 0 [20091015-10:22:07.291633655] msec_range[16] 0.020000 - 0.050000 : 0 [20091015-10:22:07.294576228] msec_range[17] 0.010000 - 0.020000 : 22 [20091015-10:22:07.297686359] msec_range[18] 0.000000 - 0.010000 : 107 [20091015-10:22:07.300549061] [20091015-10:22:07.304017166] [20091015-10:22:07.307020843] [20091015-10:22:07.309672834] [20091015-10:22:07.312360104] 0.1% User Time [20091015-10:22:07.315330024] 3.9% System Time [20091015-10:22:07.319029249] 4.1% CPU Utilization [20091015-10:22:07.322067743] Profilers reporting [20091015-10:22:07.324482339] /autobench/scripts/doprofilers: line 2: 3143 Terminated ${CMDS[$i]} [20091015-10:22:07.327394709] /autobench/scripts/doprofilers: line 2: 3158 Terminated ${CMDS[$i]} [20091015-10:22:07.330100847] /autobench/scripts/doprofilers: line 2: 3190 Terminated ${CMDS[$i]} [20091015-10:22:29.564981807] Profilers postprocessing [20091015-10:22:29.688322979] Processing File : iostat.001 [20091015-10:22:29.690575718] Discovered iostat_interval=[5] [20091015-10:22:30.428277990] Processing Directory : sar.breakout.001 [20091015-10:22:30.430913550] Discovered sar_interval=[5] [20091015-10:22:30.602648001] Processing File : mpstat.001 [20091015-10:22:30.605016533] Discovered mpstat_interval=[5] [20091015-10:22:31.751848272] Stopping profiling. [20091015-10:22:31.759288529] Killing daemon. [20091015-10:22:32.960469003] Processing File : oprofile.001 [20091015-10:22:32.962900105] Processing File : oprofile-brief.001 [20091015-10:22:33.849270342] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-10-15_0953/btrfs10-15' [20091015-10:22:36.616983052] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20091015-10:22:37.880164763] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20091015-10:22:38.338813248] 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 [20091015-10:22:38.391178428] 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' [20091015-10:22:38.441491733] new log requested [20091015-10:22:38.471516977] Running command ffsb [20091015-10:22:48.934043452] 10/15/2009-10:22:48 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb Succeeded [20091015-10:22:48.945279979] Importing argument : reuse=1 [20091015-10:22:48.958944691] Importing argument : num_threads=16 [20091015-10:22:48.987776345] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20091015-10:22:49.064217377] FFSB version 6.0-RC2.1 started [20091015-10:22:49.066440875] [20091015-10:22:49.132806814] benchmark time = 300 [20091015-10:22:49.135127544] ThreadGroup 0 [20091015-10:22:49.137180663] ================ [20091015-10:22:49.139511172] num_threads = 16 [20091015-10:22:49.141614432] [20091015-10:22:49.143531058] read_random = on [20091015-10:22:49.145484525] read_size = 5242880 (5MB) [20091015-10:22:49.147425651] read_blocksize = 4096 (4KB) [20091015-10:22:49.149458372] read_skip = off [20091015-10:22:49.151383038] read_skipsize = 0 (0B) [20091015-10:22:49.153355242] [20091015-10:22:49.155293343] write_random = off [20091015-10:22:49.157249198] write_size = 0 (0B) [20091015-10:22:49.159125355] fsync_file = 0 [20091015-10:22:49.161062623] write_blocksize = 0 (0B) [20091015-10:22:49.163175256] wait time = 0 [20091015-10:22:49.165282105] [20091015-10:22:49.167205461] op weights [20091015-10:22:49.169440263] read = 1 (100.00%) [20091015-10:22:49.171546787] readall = 0 (0.00%) [20091015-10:22:49.173523946] write = 0 (0.00%) [20091015-10:22:49.175427479] create = 0 (0.00%) [20091015-10:22:49.177390079] append = 0 (0.00%) [20091015-10:22:49.179328585] delete = 0 (0.00%) [20091015-10:22:49.181271371] metaop = 0 (0.00%) [20091015-10:22:49.183175303] createdir = 0 (0.00%) [20091015-10:22:49.185121812] stat = 0 (0.00%) [20091015-10:22:49.187000963] writeall = 0 (0.00%) [20091015-10:22:49.188925293] writeall_fsync = 0 (0.00%) [20091015-10:22:49.190837613] open_close = 0 (0.00%) [20091015-10:22:49.192786802] write_fsync = 0 (0.00%) [20091015-10:22:49.194804550] create_fsync = 0 (0.00%) [20091015-10:22:49.196737412] append_fsync = 0 (0.00%) [20091015-10:22:49.198768311] [20091015-10:22:49.200896897] FileSystem /mnt/ffsb1 [20091015-10:22:49.202915938] ========== [20091015-10:22:49.204807197] num_dirs = 0 [20091015-10:22:49.206770678] starting files = 1024 [20091015-10:22:49.208705712] [20091015-10:22:49.210677524] min file size = 104857600 (100MB) [20091015-10:22:49.212571882] max file size = 104857600 (100MB) [20091015-10:22:49.214563747] directio = off [20091015-10:22:49.216511521] alignedio = on [20091015-10:22:49.218472239] bufferedio = off [20091015-10:22:49.220366704] [20091015-10:22:49.222291053] aging is off [20091015-10:22:49.224183359] current utilization = 4.48% [20091015-10:22:49.226111575] [20091015-10:22:49.227995441] checking existing fs: /mnt/ffsb1 [20091015-10:22:49.680098625] fs setup took 0 secs [20091015-10:22:51.098109105] Syncing()...1 sec [20091015-10:22:51.100384188] Starting Actual Benchmark At: Thu Oct 15 10:22:51 2009 [20091015-10:22:51.116242292] [20091015-10:27:58.794712287] Syncing()...3 sec [20091015-10:27:58.798092872] FFSB benchmark finished at: Thu Oct 15 10:27:58 2009 [20091015-10:27:58.801390071] [20091015-10:27:58.804625068] Results: [20091015-10:27:58.824761932] Benchmark took 307.55 sec [20091015-10:27:58.827941316] [20091015-10:27:58.831030695] Total Results [20091015-10:27:58.850768697] =============== [20091015-10:27:58.853662607] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20091015-10:27:58.856881585] ======= ============ ========= ======= =========== ========== [20091015-10:27:58.860324629] read : 1431040 4652.96 100.000% 100.000% 18.2MB/sec [20091015-10:27:58.863948186] - [20091015-10:27:58.867731976] 4652.96 Transactions per Second [20091015-10:27:58.870538885] [20091015-10:27:58.873551426] Throughput Results [20091015-10:27:58.893980448] =================== [20091015-10:27:58.897423453] Read Throughput: 18.2MB/sec [20091015-10:27:58.900594990] [20091015-10:27:58.906365181] System Call Latency statistics in millisecs [20091015-10:27:58.911445450] ===== [20091015-10:27:58.914992293] Min Avg Max Total Calls [20091015-10:27:58.920360838] ======== ======== ======== ============ [20091015-10:27:58.923723081] [ open] 0.007000 0.071004 4.870000 1118 [20091015-10:27:58.927267395] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-10:27:58.930810485] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-10:27:58.935180412] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-10:27:58.939600102] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-10:27:58.943496591] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-10:27:58.948241339] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-10:27:58.951332832] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-10:27:58.957058792] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-10:27:58.960340149] msec_range[8] 10.000000 - 20.000000 : 0 [20091015-10:27:58.964343949] msec_range[9] 5.000000 - 10.000000 : 0 [20091015-10:27:58.975596377] msec_range[10] 2.000000 - 5.000000 : 4 [20091015-10:27:58.978520466] msec_range[11] 1.000000 - 2.000000 : 0 [20091015-10:27:58.981696265] msec_range[12] 0.500000 - 1.000000 : 0 [20091015-10:27:58.985055900] msec_range[13] 0.200000 - 0.500000 : 0 [20091015-10:27:58.988171002] msec_range[14] 0.100000 - 0.200000 : 124 [20091015-10:27:58.991769604] msec_range[15] 0.050000 - 0.100000 : 418 [20091015-10:27:58.994800322] msec_range[16] 0.020000 - 0.050000 : 536 [20091015-10:27:58.998158524] msec_range[17] 0.010000 - 0.020000 : 24 [20091015-10:27:59.000986614] msec_range[18] 0.000000 - 0.010000 : 12 [20091015-10:27:59.003869388] [20091015-10:27:59.006729950] [ read] 0.001000 3.376709 114.503998 1431040 [20091015-10:27:59.009416801] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-10:27:59.012288047] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-10:27:59.015654150] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-10:27:59.018691849] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-10:27:59.021651009] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-10:27:59.024919339] msec_range[5] 100.000000 - 200.000000 : 6 [20091015-10:27:59.028734311] msec_range[6] 50.000000 - 100.000000 : 39 [20091015-10:27:59.031510493] msec_range[7] 20.000000 - 50.000000 : 1355 [20091015-10:27:59.034361402] msec_range[8] 10.000000 - 20.000000 : 22741 [20091015-10:27:59.037193093] msec_range[9] 5.000000 - 10.000000 : 325543 [20091015-10:27:59.040032138] msec_range[10] 2.000000 - 5.000000 : 632774 [20091015-10:27:59.042982441] msec_range[11] 1.000000 - 2.000000 : 62288 [20091015-10:27:59.045990943] msec_range[12] 0.500000 - 1.000000 : 110111 [20091015-10:27:59.049037479] msec_range[13] 0.200000 - 0.500000 : 151463 [20091015-10:27:59.051853395] msec_range[14] 0.100000 - 0.200000 : 106 [20091015-10:27:59.054823983] msec_range[15] 0.050000 - 0.100000 : 167 [20091015-10:27:59.057994703] msec_range[16] 0.020000 - 0.050000 : 3320 [20091015-10:27:59.060920822] msec_range[17] 0.010000 - 0.020000 : 22828 [20091015-10:27:59.063792477] msec_range[18] 0.000000 - 0.010000 : 98299 [20091015-10:27:59.066496816] [20091015-10:27:59.069293887] [ lseek] 0.000000 0.001611 5.424000 1431040 [20091015-10:27:59.072636305] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-10:27:59.110105047] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-10:27:59.123666988] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-10:27:59.127252104] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-10:27:59.153227913] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-10:27:59.156726852] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-10:27:59.160998740] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-10:27:59.167401667] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-10:27:59.170788040] msec_range[8] 10.000000 - 20.000000 : 0 [20091015-10:27:59.175533344] msec_range[9] 5.000000 - 10.000000 : 1 [20091015-10:27:59.179408906] msec_range[10] 2.000000 - 5.000000 : 9 [20091015-10:27:59.182984538] msec_range[11] 1.000000 - 2.000000 : 8 [20091015-10:27:59.187666589] msec_range[12] 0.500000 - 1.000000 : 16 [20091015-10:27:59.196042197] msec_range[13] 0.200000 - 0.500000 : 25 [20091015-10:27:59.200206150] msec_range[14] 0.100000 - 0.200000 : 102 [20091015-10:27:59.206688767] msec_range[15] 0.050000 - 0.100000 : 153 [20091015-10:27:59.216090564] msec_range[16] 0.020000 - 0.050000 : 821 [20091015-10:27:59.219939757] msec_range[17] 0.010000 - 0.020000 : 4326 [20091015-10:27:59.225335190] msec_range[18] 0.000000 - 0.010000 : 1425579 [20091015-10:27:59.229150295] [20091015-10:27:59.232334408] [ close] 0.003000 0.009222 0.103000 1118 [20091015-10:27:59.236272943] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-10:27:59.240236965] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-10:27:59.244262920] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-10:27:59.248301528] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-10:27:59.251534864] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-10:27:59.257839816] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-10:27:59.262588248] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-10:27:59.266023588] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-10:27:59.270192405] msec_range[8] 10.000000 - 20.000000 : 0 [20091015-10:27:59.273823522] msec_range[9] 5.000000 - 10.000000 : 0 [20091015-10:27:59.277910843] msec_range[10] 2.000000 - 5.000000 : 0 [20091015-10:27:59.281285062] msec_range[11] 1.000000 - 2.000000 : 0 [20091015-10:27:59.287598810] msec_range[12] 0.500000 - 1.000000 : 0 [20091015-10:27:59.293828245] msec_range[13] 0.200000 - 0.500000 : 0 [20091015-10:27:59.305652089] msec_range[14] 0.100000 - 0.200000 : 1 [20091015-10:27:59.316711617] msec_range[15] 0.050000 - 0.100000 : 0 [20091015-10:27:59.321765420] msec_range[16] 0.020000 - 0.050000 : 7 [20091015-10:27:59.326899359] msec_range[17] 0.010000 - 0.020000 : 283 [20091015-10:27:59.331428610] msec_range[18] 0.000000 - 0.010000 : 827 [20091015-10:27:59.337053285] [20091015-10:27:59.340360801] [20091015-10:27:59.344204830] [20091015-10:27:59.349306992] [20091015-10:27:59.354564327] 1.4% User Time [20091015-10:27:59.358400660] 43.8% System Time [20091015-10:27:59.361886681] 45.3% CPU Utilization [20091015-10:27:59.366295433] Profilers reporting [20091015-10:28:53.362313555] Profilers postprocessing [20091015-10:28:53.590699793] Processing File : iostat.001 [20091015-10:28:53.593147293] Discovered iostat_interval=[5] [20091015-10:28:54.370053963] Processing Directory : sar.breakout.001 [20091015-10:28:54.372259590] Discovered sar_interval=[5] [20091015-10:28:54.544020462] Processing File : mpstat.001 [20091015-10:28:54.546196411] Discovered mpstat_interval=[5] [20091015-10:28:55.693397837] Stopping profiling. [20091015-10:28:55.700384254] Killing daemon. [20091015-10:28:56.978980329] Processing File : oprofile.001 [20091015-10:28:56.981175073] Processing File : oprofile-brief.001 [20091015-10:28:58.370118247] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-10-15_0953/btrfs10-15' [20091015-10:29:02.198786014] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20091015-10:29:05.397908005] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20091015-10:29:05.864741868] 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 [20091015-10:29:05.918618081] 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' [20091015-10:29:05.966526164] new log requested [20091015-10:29:05.994525920] Running command ffsb [20091015-10:29:17.426630726] 10/15/2009-10:29:17 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb Succeeded [20091015-10:29:17.438320683] Importing argument : reuse=1 [20091015-10:29:17.452018784] Importing argument : num_threads=128 [20091015-10:29:17.481129090] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20091015-10:29:17.582703257] FFSB version 6.0-RC2.1 started [20091015-10:29:17.584883691] [20091015-10:29:18.126074584] benchmark time = 300 [20091015-10:29:18.128459922] ThreadGroup 0 [20091015-10:29:18.130824670] ================ [20091015-10:29:18.133097406] num_threads = 128 [20091015-10:29:18.135045860] [20091015-10:29:18.137040609] read_random = on [20091015-10:29:18.138989002] read_size = 5242880 (5MB) [20091015-10:29:18.140970767] read_blocksize = 4096 (4KB) [20091015-10:29:18.142911688] read_skip = off [20091015-10:29:18.144925448] read_skipsize = 0 (0B) [20091015-10:29:18.146826133] [20091015-10:29:18.148796516] write_random = off [20091015-10:29:18.150763808] write_size = 0 (0B) [20091015-10:29:18.152714830] fsync_file = 0 [20091015-10:29:18.154616121] write_blocksize = 0 (0B) [20091015-10:29:18.156586007] wait time = 0 [20091015-10:29:18.158464932] [20091015-10:29:18.160394021] op weights [20091015-10:29:18.162228296] read = 1 (100.00%) [20091015-10:29:18.164298397] readall = 0 (0.00%) [20091015-10:29:18.166230862] write = 0 (0.00%) [20091015-10:29:18.168150317] create = 0 (0.00%) [20091015-10:29:18.170094331] append = 0 (0.00%) [20091015-10:29:18.172081428] delete = 0 (0.00%) [20091015-10:29:18.173965318] metaop = 0 (0.00%) [20091015-10:29:18.176062008] createdir = 0 (0.00%) [20091015-10:29:18.178163190] stat = 0 (0.00%) [20091015-10:29:18.180575815] writeall = 0 (0.00%) [20091015-10:29:18.182788558] writeall_fsync = 0 (0.00%) [20091015-10:29:18.184849146] open_close = 0 (0.00%) [20091015-10:29:18.186822703] write_fsync = 0 (0.00%) [20091015-10:29:18.188883134] create_fsync = 0 (0.00%) [20091015-10:29:18.190827214] append_fsync = 0 (0.00%) [20091015-10:29:18.192790814] [20091015-10:29:18.194735520] FileSystem /mnt/ffsb1 [20091015-10:29:18.196765740] ========== [20091015-10:29:18.198697176] num_dirs = 0 [20091015-10:29:18.200649163] starting files = 1024 [20091015-10:29:18.202554239] [20091015-10:29:18.204539548] min file size = 104857600 (100MB) [20091015-10:29:18.206594341] max file size = 104857600 (100MB) [20091015-10:29:18.208526283] directio = off [20091015-10:29:18.210583645] alignedio = on [20091015-10:29:18.212545761] bufferedio = off [20091015-10:29:18.214506045] [20091015-10:29:18.216388244] aging is off [20091015-10:29:18.218369131] current utilization = 4.48% [20091015-10:29:18.220238720] [20091015-10:29:18.222188944] checking existing fs: /mnt/ffsb1 [20091015-10:29:18.690326295] fs setup took 0 secs [20091015-10:29:20.120008682] Syncing()...1 sec [20091015-10:29:20.125147220] Starting Actual Benchmark At: Thu Oct 15 10:29:20 2009 [20091015-10:29:20.141505026] [20091015-10:34:30.330361640] Syncing()...2 sec [20091015-10:34:30.333920629] FFSB benchmark finished at: Thu Oct 15 10:34:30 2009 [20091015-10:34:30.337134110] [20091015-10:34:30.340597356] Results: [20091015-10:34:30.360336948] Benchmark took 310.09 sec [20091015-10:34:30.363306803] [20091015-10:34:30.366355749] Total Results [20091015-10:34:30.387131165] =============== [20091015-10:34:30.391519486] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20091015-10:34:30.395141877] ======= ============ ========= ======= =========== ========== [20091015-10:34:30.398283402] read : 5904640 19041.64 100.000% 100.000% 74.4MB/sec [20091015-10:34:30.401710668] - [20091015-10:34:30.405911702] 19041.64 Transactions per Second [20091015-10:34:30.414406622] [20091015-10:34:30.420613908] Throughput Results [20091015-10:34:30.441446172] =================== [20091015-10:34:30.487840930] Read Throughput: 74.4MB/sec [20091015-10:34:30.491173783] [20091015-10:34:30.494613413] System Call Latency statistics in millisecs [20091015-10:34:30.497989329] ===== [20091015-10:34:30.501293434] Min Avg Max Total Calls [20091015-10:34:30.510022432] ======== ======== ======== ============ [20091015-10:34:30.514169968] [ open] 0.007000 0.068509 26.202000 4613 [20091015-10:34:30.519208737] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-10:34:30.521880824] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-10:34:30.525269289] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-10:34:30.528562894] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-10:34:30.531950831] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-10:34:30.535111873] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-10:34:30.538426133] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-10:34:30.541685741] msec_range[7] 20.000000 - 50.000000 : 2 [20091015-10:34:30.544212217] msec_range[8] 10.000000 - 20.000000 : 1 [20091015-10:34:30.547310105] msec_range[9] 5.000000 - 10.000000 : 3 [20091015-10:34:30.549979531] msec_range[10] 2.000000 - 5.000000 : 0 [20091015-10:34:30.553405294] msec_range[11] 1.000000 - 2.000000 : 0 [20091015-10:34:30.556199407] msec_range[12] 0.500000 - 1.000000 : 1 [20091015-10:34:30.559391416] msec_range[13] 0.200000 - 0.500000 : 6 [20091015-10:34:30.562247860] msec_range[14] 0.100000 - 0.200000 : 286 [20091015-10:34:30.565197685] msec_range[15] 0.050000 - 0.100000 : 1889 [20091015-10:34:30.567990302] msec_range[16] 0.020000 - 0.050000 : 2188 [20091015-10:34:30.570840764] msec_range[17] 0.010000 - 0.020000 : 207 [20091015-10:34:30.573914745] msec_range[18] 0.000000 - 0.010000 : 30 [20091015-10:34:30.576901328] [20091015-10:34:30.579770979] [ read] 0.001000 6.603051 517.971985 5904640 [20091015-10:34:30.582651585] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-10:34:30.585536738] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-10:34:30.588520831] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-10:34:30.591422093] msec_range[3] 500.000000 - 1000.000000 : 3 [20091015-10:34:30.594444842] msec_range[4] 200.000000 - 500.000000 : 233 [20091015-10:34:30.597284268] msec_range[5] 100.000000 - 200.000000 : 1009 [20091015-10:34:30.600277419] msec_range[6] 50.000000 - 100.000000 : 4492 [20091015-10:34:30.603379000] msec_range[7] 20.000000 - 50.000000 : 134336 [20091015-10:34:30.606123518] msec_range[8] 10.000000 - 20.000000 : 796282 [20091015-10:34:30.609101023] msec_range[9] 5.000000 - 10.000000 : 2567970 [20091015-10:34:30.612087157] msec_range[10] 2.000000 - 5.000000 : 1763724 [20091015-10:34:30.614970635] msec_range[11] 1.000000 - 2.000000 : 56256 [20091015-10:34:30.617899507] msec_range[12] 0.500000 - 1.000000 : 28708 [20091015-10:34:30.620832549] msec_range[13] 0.200000 - 0.500000 : 3015 [20091015-10:34:30.623734622] msec_range[14] 0.100000 - 0.200000 : 250 [20091015-10:34:30.626815978] msec_range[15] 0.050000 - 0.100000 : 701 [20091015-10:34:30.629945214] msec_range[16] 0.020000 - 0.050000 : 23317 [20091015-10:34:30.633030527] msec_range[17] 0.010000 - 0.020000 : 82715 [20091015-10:34:30.635940421] msec_range[18] 0.000000 - 0.010000 : 441629 [20091015-10:34:30.639649858] [20091015-10:34:30.642585790] [ lseek] 0.000000 0.001658 1.551000 5904640 [20091015-10:34:30.645632320] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-10:34:30.651107497] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-10:34:30.661093820] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-10:34:30.665188437] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-10:34:30.668681959] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-10:34:30.672564545] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-10:34:30.675966540] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-10:34:30.679482643] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-10:34:30.683104665] msec_range[8] 10.000000 - 20.000000 : 0 [20091015-10:34:30.686726423] msec_range[9] 5.000000 - 10.000000 : 0 [20091015-10:34:30.690245957] msec_range[10] 2.000000 - 5.000000 : 0 [20091015-10:34:30.693445988] msec_range[11] 1.000000 - 2.000000 : 1 [20091015-10:34:30.699079091] msec_range[12] 0.500000 - 1.000000 : 3 [20091015-10:34:30.704062202] msec_range[13] 0.200000 - 0.500000 : 8 [20091015-10:34:30.709234379] msec_range[14] 0.100000 - 0.200000 : 65 [20091015-10:34:30.714750996] msec_range[15] 0.050000 - 0.100000 : 623 [20091015-10:34:30.722847637] msec_range[16] 0.020000 - 0.050000 : 9288 [20091015-10:34:30.732347502] msec_range[17] 0.010000 - 0.020000 : 22037 [20091015-10:34:30.735633426] msec_range[18] 0.000000 - 0.010000 : 5872615 [20091015-10:34:30.740119127] [20091015-10:34:30.744250252] [ close] 0.003000 0.009413 0.076000 4613 [20091015-10:34:30.748562856] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-10:34:30.752251240] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-10:34:30.760029116] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-10:34:30.778124596] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-10:34:30.782182764] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-10:34:30.785171347] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-10:34:30.787947569] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-10:34:30.791239221] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-10:34:30.794278637] msec_range[8] 10.000000 - 20.000000 : 0 [20091015-10:34:30.797630139] msec_range[9] 5.000000 - 10.000000 : 0 [20091015-10:34:30.801163240] msec_range[10] 2.000000 - 5.000000 : 0 [20091015-10:34:30.804212026] msec_range[11] 1.000000 - 2.000000 : 0 [20091015-10:34:30.807951793] msec_range[12] 0.500000 - 1.000000 : 0 [20091015-10:34:30.810801461] msec_range[13] 0.200000 - 0.500000 : 0 [20091015-10:34:30.813584898] msec_range[14] 0.100000 - 0.200000 : 0 [20091015-10:34:30.816565082] msec_range[15] 0.050000 - 0.100000 : 5 [20091015-10:34:30.819592791] msec_range[16] 0.020000 - 0.050000 : 95 [20091015-10:34:30.822621649] msec_range[17] 0.010000 - 0.020000 : 1183 [20091015-10:34:30.825739693] msec_range[18] 0.000000 - 0.010000 : 3330 [20091015-10:34:30.829273978] [20091015-10:34:30.832236982] [20091015-10:34:30.836886337] [20091015-10:34:30.839524098] [20091015-10:34:30.845293609] 6.4% User Time [20091015-10:34:30.849345117] 195.6% System Time [20091015-10:34:30.852875038] 202.0% CPU Utilization [20091015-10:34:30.856610581] Profilers reporting [20091015-10:35:17.788517820] Profilers postprocessing [20091015-10:35:18.018404397] Processing File : iostat.001 [20091015-10:35:18.020972227] Discovered iostat_interval=[5] [20091015-10:35:18.808923917] Processing Directory : sar.breakout.001 [20091015-10:35:18.811137483] Discovered sar_interval=[5] [20091015-10:35:19.008221240] Processing File : mpstat.001 [20091015-10:35:19.010620177] Discovered mpstat_interval=[5] [20091015-10:35:20.156355721] Stopping profiling. [20091015-10:35:20.161600906] Killing daemon. [20091015-10:35:21.423421703] Processing File : oprofile.001 [20091015-10:35:21.425755453] Processing File : oprofile-brief.001 [20091015-10:35:22.838218189] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-10-15_0953/btrfs10-15' [20091015-10:35:26.716078899] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20091015-10:35:30.162331757] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20091015-10:35:30.604228195] 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 [20091015-10:35:30.658663601] 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' [20091015-10:35:30.706338219] new log requested [20091015-10:35:30.737168212] Running command ffsb [20091015-10:35:42.154716625] 10/15/2009-10:35:42 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb Succeeded [20091015-10:35:42.166423492] Importing argument : num_threads=1 [20091015-10:35:42.195137310] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20091015-10:35:42.288741823] FFSB version 6.0-RC2.1 started [20091015-10:35:42.291017476] [20091015-10:35:42.293519557] benchmark time = 300 [20091015-10:35:42.295738450] ThreadGroup 0 [20091015-10:35:42.297793907] ================ [20091015-10:35:42.299886269] num_threads = 1 [20091015-10:35:42.302142880] [20091015-10:35:42.304357962] read_random = off [20091015-10:35:42.306672317] read_size = 0 (0B) [20091015-10:35:42.308743838] read_blocksize = 0 (0B) [20091015-10:35:42.310705579] read_skip = off [20091015-10:35:42.312595020] read_skipsize = 0 (0B) [20091015-10:35:42.314584936] [20091015-10:35:42.316497260] write_random = on [20091015-10:35:42.318444327] write_size = 5242880 (5MB) [20091015-10:35:42.320322704] fsync_file = 0 [20091015-10:35:42.322265921] write_blocksize = 4096 (4KB) [20091015-10:35:42.324162495] wait time = 0 [20091015-10:35:42.326101659] [20091015-10:35:42.327943478] op weights [20091015-10:35:42.329876823] read = 0 (0.00%) [20091015-10:35:42.331758197] readall = 0 (0.00%) [20091015-10:35:42.333735289] write = 1 (100.00%) [20091015-10:35:42.335838544] create = 0 (0.00%) [20091015-10:35:42.337926081] append = 0 (0.00%) [20091015-10:35:42.339941348] delete = 0 (0.00%) [20091015-10:35:42.342100848] metaop = 0 (0.00%) [20091015-10:35:42.344039692] createdir = 0 (0.00%) [20091015-10:35:42.345994180] stat = 0 (0.00%) [20091015-10:35:42.347903286] writeall = 0 (0.00%) [20091015-10:35:42.349935878] writeall_fsync = 0 (0.00%) [20091015-10:35:42.351809617] open_close = 0 (0.00%) [20091015-10:35:42.353742555] write_fsync = 0 (0.00%) [20091015-10:35:42.355712254] create_fsync = 0 (0.00%) [20091015-10:35:42.357736208] append_fsync = 0 (0.00%) [20091015-10:35:42.359627848] [20091015-10:35:42.361578721] FileSystem /mnt/ffsb1 [20091015-10:35:42.363520510] ========== [20091015-10:35:42.365542644] num_dirs = 0 [20091015-10:35:42.367416996] starting files = 1024 [20091015-10:35:42.369413552] [20091015-10:35:42.371321116] min file size = 104857600 (100MB) [20091015-10:35:42.373283594] max file size = 104857600 (100MB) [20091015-10:35:42.375151719] directio = off [20091015-10:35:42.377088636] alignedio = on [20091015-10:35:42.378979343] bufferedio = off [20091015-10:35:42.380957271] [20091015-10:35:42.382835714] aging is off [20091015-10:35:42.384777041] current utilization = 4.48% [20091015-10:35:42.386642040] [20091015-10:35:42.388543993] creating new fileset /mnt/ffsb1 [20091015-10:40:15.353452193] fs setup took 272 secs [20091015-10:40:46.743255374] Syncing()...31 sec [20091015-10:40:46.746166546] Starting Actual Benchmark At: Thu Oct 15 10:40:46 2009 [20091015-10:40:46.763819021] [20091015-10:45:52.890906456] Syncing()...4 sec [20091015-10:45:52.903415512] FFSB benchmark finished at: Thu Oct 15 10:45:52 2009 [20091015-10:45:52.907072633] [20091015-10:45:52.910896366] Results: [20091015-10:45:52.933630329] Benchmark took 305.84 sec [20091015-10:45:52.937873076] [20091015-10:45:52.941317324] Total Results [20091015-10:45:52.961734527] =============== [20091015-10:45:52.964954508] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20091015-10:45:52.968380465] ======= ============ ========= ======= =========== ========== [20091015-10:45:52.971931248] write : 2364160 7729.96 100.000% 100.000% 30.2MB/sec [20091015-10:45:52.976510382] - [20091015-10:45:52.981468675] 7729.96 Transactions per Second [20091015-10:45:52.984643144] [20091015-10:45:52.987754404] Throughput Results [20091015-10:45:53.008387377] =================== [20091015-10:45:53.011908891] Write Throughput: 30.2MB/sec [20091015-10:45:53.015880990] [20091015-10:45:53.020960170] System Call Latency statistics in millisecs [20091015-10:45:53.024481748] ===== [20091015-10:45:53.027992548] Min Avg Max Total Calls [20091015-10:45:53.032645183] ======== ======== ======== ============ [20091015-10:45:53.035951184] [ open] 0.015000 0.102874 6.609000 1847 [20091015-10:45:53.039984782] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-10:45:53.045223862] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-10:45:53.052806377] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-10:45:53.059311667] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-10:45:53.062800325] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-10:45:53.066478924] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-10:45:53.069758258] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-10:45:53.073121540] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-10:45:53.076585319] msec_range[8] 10.000000 - 20.000000 : 0 [20091015-10:45:53.081242014] msec_range[9] 5.000000 - 10.000000 : 1 [20091015-10:45:53.084541786] msec_range[10] 2.000000 - 5.000000 : 5 [20091015-10:45:53.088170337] msec_range[11] 1.000000 - 2.000000 : 3 [20091015-10:45:53.091669124] msec_range[12] 0.500000 - 1.000000 : 8 [20091015-10:45:53.095252242] msec_range[13] 0.200000 - 0.500000 : 127 [20091015-10:45:53.098887202] msec_range[14] 0.100000 - 0.200000 : 482 [20091015-10:45:53.103694682] msec_range[15] 0.050000 - 0.100000 : 493 [20091015-10:45:53.107348194] msec_range[16] 0.020000 - 0.050000 : 721 [20091015-10:45:53.110627475] msec_range[17] 0.010000 - 0.020000 : 7 [20091015-10:45:53.114048764] msec_range[18] 0.000000 - 0.010000 : 0 [20091015-10:45:53.117858660] [20091015-10:45:53.131378542] [ write] 0.007000 0.124159 710.737000 2364160 [20091015-10:45:53.135110476] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-10:45:53.138418332] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-10:45:53.141962598] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-10:45:53.145344005] msec_range[3] 500.000000 - 1000.000000 : 9 [20091015-10:45:53.148715937] msec_range[4] 200.000000 - 500.000000 : 27 [20091015-10:45:53.151857619] msec_range[5] 100.000000 - 200.000000 : 33 [20091015-10:45:53.155344152] msec_range[6] 50.000000 - 100.000000 : 111 [20091015-10:45:53.158824337] msec_range[7] 20.000000 - 50.000000 : 534 [20091015-10:45:53.162392836] msec_range[8] 10.000000 - 20.000000 : 1461 [20091015-10:45:53.166823172] msec_range[9] 5.000000 - 10.000000 : 2915 [20091015-10:45:53.170149613] msec_range[10] 2.000000 - 5.000000 : 6417 [20091015-10:45:53.181584437] msec_range[11] 1.000000 - 2.000000 : 4578 [20091015-10:45:53.187185554] msec_range[12] 0.500000 - 1.000000 : 6809 [20091015-10:45:53.193444104] msec_range[13] 0.200000 - 0.500000 : 63380 [20091015-10:45:53.199169254] msec_range[14] 0.100000 - 0.200000 : 549289 [20091015-10:45:53.202652709] msec_range[15] 0.050000 - 0.100000 : 1029269 [20091015-10:45:53.206518668] msec_range[16] 0.020000 - 0.050000 : 338689 [20091015-10:45:53.210562816] msec_range[17] 0.010000 - 0.020000 : 359135 [20091015-10:45:53.218399181] msec_range[18] 0.000000 - 0.010000 : 1504 [20091015-10:45:53.221802803] [20091015-10:45:53.225977938] [ lseek] 0.000000 0.001672 16.503000 2364160 [20091015-10:45:53.266842040] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-10:45:53.271097865] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-10:45:53.275488505] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-10:45:53.280725868] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-10:45:53.284273711] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-10:45:53.288126759] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-10:45:53.292345454] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-10:45:53.296299142] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-10:45:53.300018425] msec_range[8] 10.000000 - 20.000000 : 2 [20091015-10:45:53.307287062] msec_range[9] 5.000000 - 10.000000 : 7 [20091015-10:45:53.311113631] msec_range[10] 2.000000 - 5.000000 : 28 [20091015-10:45:53.315719718] msec_range[11] 1.000000 - 2.000000 : 15 [20091015-10:45:53.319315633] msec_range[12] 0.500000 - 1.000000 : 18 [20091015-10:45:53.323094912] msec_range[13] 0.200000 - 0.500000 : 38 [20091015-10:45:53.326860420] msec_range[14] 0.100000 - 0.200000 : 24 [20091015-10:45:53.330480288] msec_range[15] 0.050000 - 0.100000 : 279 [20091015-10:45:53.333589929] msec_range[16] 0.020000 - 0.050000 : 2356 [20091015-10:45:53.336562492] msec_range[17] 0.010000 - 0.020000 : 4036 [20091015-10:45:53.339838911] msec_range[18] 0.000000 - 0.010000 : 2357357 [20091015-10:45:53.343494772] [20091015-10:45:53.353459504] [ close] 0.003000 0.010115 0.374000 1847 [20091015-10:45:53.359145278] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-10:45:53.381063635] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-10:45:53.384451124] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-10:45:53.387712188] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-10:45:53.391604616] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-10:45:53.395572270] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-10:45:53.399637862] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-10:45:53.402824717] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-10:45:53.406232598] msec_range[8] 10.000000 - 20.000000 : 0 [20091015-10:45:53.415968561] msec_range[9] 5.000000 - 10.000000 : 0 [20091015-10:45:53.420349695] msec_range[10] 2.000000 - 5.000000 : 0 [20091015-10:45:53.425367977] msec_range[11] 1.000000 - 2.000000 : 0 [20091015-10:45:53.429272404] msec_range[12] 0.500000 - 1.000000 : 0 [20091015-10:45:53.432732457] msec_range[13] 0.200000 - 0.500000 : 1 [20091015-10:45:53.440264704] msec_range[14] 0.100000 - 0.200000 : 0 [20091015-10:45:53.443744124] msec_range[15] 0.050000 - 0.100000 : 1 [20091015-10:45:53.447074870] msec_range[16] 0.020000 - 0.050000 : 33 [20091015-10:45:53.450403718] msec_range[17] 0.010000 - 0.020000 : 624 [20091015-10:45:53.454722519] msec_range[18] 0.000000 - 0.010000 : 1188 [20091015-10:45:53.459692702] [20091015-10:45:53.464269639] [20091015-10:45:53.468419618] [20091015-10:45:53.474339548] [20091015-10:45:53.481030643] 2.0% User Time [20091015-10:45:53.486023473] 54.0% System Time [20091015-10:45:53.489693447] 56.0% CPU Utilization [20091015-10:45:53.493394643] Profilers reporting [20091015-10:46:34.400555069] Profilers postprocessing [20091015-10:46:34.723104944] Processing File : iostat.001 [20091015-10:46:34.725573996] Discovered iostat_interval=[5] [20091015-10:46:35.562056401] Processing Directory : sar.breakout.001 [20091015-10:46:35.564281662] Discovered sar_interval=[5] [20091015-10:46:35.739297173] Processing File : mpstat.001 [20091015-10:46:35.741802569] Discovered mpstat_interval=[5] [20091015-10:46:36.894813382] Stopping profiling. [20091015-10:46:36.902513145] Killing daemon. [20091015-10:46:38.208787082] Processing File : oprofile.001 [20091015-10:46:38.211184204] Processing File : oprofile-brief.001 [20091015-10:46:39.897404140] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-10-15_0953/btrfs10-15' [20091015-10:46:44.501804551] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20091015-10:46:48.822179635] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20091015-10:46:48.975567901] 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 [20091015-10:46:49.027411032] 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' [20091015-10:46:49.076665131] new log requested [20091015-10:46:49.110153103] Running command ffsb [20091015-10:47:00.686374998] 10/15/2009-10:47:00 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb Succeeded [20091015-10:47:00.697256210] Importing argument : num_threads=16 [20091015-10:47:00.726888245] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20091015-10:47:00.826449928] FFSB version 6.0-RC2.1 started [20091015-10:47:00.828877980] [20091015-10:47:00.891854873] benchmark time = 300 [20091015-10:47:00.893876290] ThreadGroup 0 [20091015-10:47:00.896017360] ================ [20091015-10:47:00.898291402] num_threads = 16 [20091015-10:47:00.900553429] [20091015-10:47:00.902641337] read_random = off [20091015-10:47:00.904889955] read_size = 0 (0B) [20091015-10:47:00.907180603] read_blocksize = 0 (0B) [20091015-10:47:00.909331521] read_skip = off [20091015-10:47:00.911248918] read_skipsize = 0 (0B) [20091015-10:47:00.913194390] [20091015-10:47:00.915160228] write_random = on [20091015-10:47:00.917058507] write_size = 5242880 (5MB) [20091015-10:47:00.919016618] fsync_file = 0 [20091015-10:47:00.920912616] write_blocksize = 4096 (4KB) [20091015-10:47:00.922888159] wait time = 0 [20091015-10:47:00.925150709] [20091015-10:47:00.927260740] op weights [20091015-10:47:00.929211532] read = 0 (0.00%) [20091015-10:47:00.931248193] readall = 0 (0.00%) [20091015-10:47:00.933173660] write = 1 (100.00%) [20091015-10:47:00.935154284] create = 0 (0.00%) [20091015-10:47:00.937150466] append = 0 (0.00%) [20091015-10:47:00.939240190] delete = 0 (0.00%) [20091015-10:47:00.941297084] metaop = 0 (0.00%) [20091015-10:47:00.943455599] createdir = 0 (0.00%) [20091015-10:47:00.945579937] stat = 0 (0.00%) [20091015-10:47:00.947665022] writeall = 0 (0.00%) [20091015-10:47:00.949699904] writeall_fsync = 0 (0.00%) [20091015-10:47:00.951774471] open_close = 0 (0.00%) [20091015-10:47:00.953841382] write_fsync = 0 (0.00%) [20091015-10:47:00.955852773] create_fsync = 0 (0.00%) [20091015-10:47:00.957959545] append_fsync = 0 (0.00%) [20091015-10:47:00.960386072] [20091015-10:47:00.962767521] FileSystem /mnt/ffsb1 [20091015-10:47:00.964696486] ========== [20091015-10:47:00.966846168] num_dirs = 0 [20091015-10:47:00.968908035] starting files = 1024 [20091015-10:47:00.970858009] [20091015-10:47:00.972900505] min file size = 104857600 (100MB) [20091015-10:47:00.975501017] max file size = 104857600 (100MB) [20091015-10:47:00.977778162] directio = off [20091015-10:47:00.979676324] alignedio = on [20091015-10:47:00.981649311] bufferedio = off [20091015-10:47:00.983665609] [20091015-10:47:00.985769153] aging is off [20091015-10:47:00.987651009] current utilization = 4.84% [20091015-10:47:00.989616133] [20091015-10:47:00.991611724] creating new fileset /mnt/ffsb1 [20091015-10:55:29.805163738] fs setup took 508 secs [20091015-10:56:09.741651963] Syncing()...40 sec [20091015-10:56:09.746915617] Starting Actual Benchmark At: Thu Oct 15 10:56:09 2009 [20091015-10:56:09.928792932] [20091015-11:01:18.464252591] Syncing()...5 sec [20091015-11:01:18.526021074] FFSB benchmark finished at: Thu Oct 15 11:01:18 2009 [20091015-11:01:18.529543647] [20091015-11:01:18.533028890] Results: [20091015-11:01:18.573535762] Benchmark took 308.47 sec [20091015-11:01:18.576760478] [20091015-11:01:18.579721033] Total Results [20091015-11:01:18.599706312] =============== [20091015-11:01:18.602524240] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20091015-11:01:18.605523131] ======= ============ ========= ======= =========== ========== [20091015-11:01:18.608639969] write : 4037120 13087.51 100.000% 100.000% 51.1MB/sec [20091015-11:01:18.612274728] - [20091015-11:01:18.615718786] 13087.51 Transactions per Second [20091015-11:01:18.619149122] [20091015-11:01:18.622497011] Throughput Results [20091015-11:01:18.642774443] =================== [20091015-11:01:18.646254687] Write Throughput: 51.1MB/sec [20091015-11:01:18.650367709] [20091015-11:01:18.653702391] System Call Latency statistics in millisecs [20091015-11:01:18.657042919] ===== [20091015-11:01:18.660247392] Min Avg Max Total Calls [20091015-11:01:18.663751877] ======== ======== ======== ============ [20091015-11:01:18.668357825] [ open] 0.008000 0.083995 8.171000 3154 [20091015-11:01:18.671372848] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-11:01:18.676204448] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-11:01:18.679790426] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-11:01:18.683127552] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-11:01:18.686083794] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-11:01:18.689098895] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-11:01:18.695473641] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-11:01:18.698499398] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-11:01:18.701543466] msec_range[8] 10.000000 - 20.000000 : 0 [20091015-11:01:18.704590085] msec_range[9] 5.000000 - 10.000000 : 3 [20091015-11:01:18.707744526] msec_range[10] 2.000000 - 5.000000 : 1 [20091015-11:01:18.710720592] msec_range[11] 1.000000 - 2.000000 : 0 [20091015-11:01:18.713812586] msec_range[12] 0.500000 - 1.000000 : 2 [20091015-11:01:18.717242568] msec_range[13] 0.200000 - 0.500000 : 69 [20091015-11:01:18.720256030] msec_range[14] 0.100000 - 0.200000 : 908 [20091015-11:01:18.723766643] msec_range[15] 0.050000 - 0.100000 : 795 [20091015-11:01:18.730317253] msec_range[16] 0.020000 - 0.050000 : 1335 [20091015-11:01:18.734655702] msec_range[17] 0.010000 - 0.020000 : 40 [20091015-11:01:18.738220198] msec_range[18] 0.000000 - 0.010000 : 1 [20091015-11:01:18.741557254] [20091015-11:01:18.744945059] [ write] 0.008000 1.178440 5281.979004 4037120 [20091015-11:01:18.748562878] msec_range[0] 5000.000000 - 10000.000000 : 5 [20091015-11:01:18.751491894] msec_range[1] 2000.000000 - 5000.000000 : 355 [20091015-11:01:18.754483147] msec_range[2] 1000.000000 - 2000.000000 : 644 [20091015-11:01:18.759065949] msec_range[3] 500.000000 - 1000.000000 : 888 [20091015-11:01:18.763096582] msec_range[4] 200.000000 - 500.000000 : 4294 [20091015-11:01:18.766646817] msec_range[5] 100.000000 - 200.000000 : 3319 [20091015-11:01:18.770260117] msec_range[6] 50.000000 - 100.000000 : 1993 [20091015-11:01:18.773655644] msec_range[7] 20.000000 - 50.000000 : 2083 [20091015-11:01:18.777452909] msec_range[8] 10.000000 - 20.000000 : 1579 [20091015-11:01:18.780145763] msec_range[9] 5.000000 - 10.000000 : 2044 [20091015-11:01:18.783060918] msec_range[10] 2.000000 - 5.000000 : 3205 [20091015-11:01:18.786369889] msec_range[11] 1.000000 - 2.000000 : 2543 [20091015-11:01:18.789333494] msec_range[12] 0.500000 - 1.000000 : 3658 [20091015-11:01:18.792448322] msec_range[13] 0.200000 - 0.500000 : 23290 [20091015-11:01:18.795344108] msec_range[14] 0.100000 - 0.200000 : 223694 [20091015-11:01:18.800053451] msec_range[15] 0.050000 - 0.100000 : 885244 [20091015-11:01:18.803646410] msec_range[16] 0.020000 - 0.050000 : 1401394 [20091015-11:01:18.806998585] msec_range[17] 0.010000 - 0.020000 : 1475989 [20091015-11:01:18.810335643] msec_range[18] 0.000000 - 0.010000 : 899 [20091015-11:01:18.813496088] [20091015-11:01:18.816595932] [ lseek] 0.000000 0.015177 5265.373047 4037120 [20091015-11:01:18.819742745] msec_range[0] 5000.000000 - 10000.000000 : 1 [20091015-11:01:18.822829371] msec_range[1] 2000.000000 - 5000.000000 : 5 [20091015-11:01:18.826075671] msec_range[2] 1000.000000 - 2000.000000 : 9 [20091015-11:01:18.829433737] msec_range[3] 500.000000 - 1000.000000 : 12 [20091015-11:01:18.832728239] msec_range[4] 200.000000 - 500.000000 : 31 [20091015-11:01:18.835650213] msec_range[5] 100.000000 - 200.000000 : 15 [20091015-11:01:18.838683799] msec_range[6] 50.000000 - 100.000000 : 8 [20091015-11:01:18.841672034] msec_range[7] 20.000000 - 50.000000 : 15 [20091015-11:01:18.845157190] msec_range[8] 10.000000 - 20.000000 : 9 [20091015-11:01:18.848080021] msec_range[9] 5.000000 - 10.000000 : 17 [20091015-11:01:18.850972485] msec_range[10] 2.000000 - 5.000000 : 47 [20091015-11:01:18.854046450] msec_range[11] 1.000000 - 2.000000 : 13 [20091015-11:01:18.857300823] msec_range[12] 0.500000 - 1.000000 : 25 [20091015-11:01:18.860230360] msec_range[13] 0.200000 - 0.500000 : 47 [20091015-11:01:18.863351014] msec_range[14] 0.100000 - 0.200000 : 210 [20091015-11:01:18.866559571] msec_range[15] 0.050000 - 0.100000 : 1095 [20091015-11:01:18.870143116] msec_range[16] 0.020000 - 0.050000 : 9601 [20091015-11:01:18.873337665] msec_range[17] 0.010000 - 0.020000 : 15146 [20091015-11:01:18.876365790] msec_range[18] 0.000000 - 0.010000 : 4010814 [20091015-11:01:18.881307617] [20091015-11:01:18.884038098] [ close] 0.004000 0.010270 0.073000 3154 [20091015-11:01:18.887098577] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-11:01:18.890076365] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-11:01:18.893345683] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-11:01:18.896573239] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-11:01:18.899697421] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-11:01:18.902476991] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-11:01:18.905446906] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-11:01:18.908354043] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-11:01:18.911429181] msec_range[8] 10.000000 - 20.000000 : 0 [20091015-11:01:18.914362582] msec_range[9] 5.000000 - 10.000000 : 0 [20091015-11:01:18.917261125] msec_range[10] 2.000000 - 5.000000 : 0 [20091015-11:01:18.920652410] msec_range[11] 1.000000 - 2.000000 : 0 [20091015-11:01:18.923829076] msec_range[12] 0.500000 - 1.000000 : 0 [20091015-11:01:18.926773701] msec_range[13] 0.200000 - 0.500000 : 0 [20091015-11:01:18.929615992] msec_range[14] 0.100000 - 0.200000 : 0 [20091015-11:01:18.932556652] msec_range[15] 0.050000 - 0.100000 : 5 [20091015-11:01:18.935632564] msec_range[16] 0.020000 - 0.050000 : 64 [20091015-11:01:18.938507056] msec_range[17] 0.010000 - 0.020000 : 1486 [20091015-11:01:18.941571620] msec_range[18] 0.000000 - 0.010000 : 1599 [20091015-11:01:18.944759246] [20091015-11:01:18.948403832] [20091015-11:01:18.951588569] [20091015-11:01:18.954910761] [20091015-11:01:18.958435046] 3.3% User Time [20091015-11:01:18.961823178] 68.2% System Time [20091015-11:01:18.973808748] 71.5% CPU Utilization [20091015-11:01:18.977866789] Profilers reporting [20091015-11:01:55.474662012] Profilers postprocessing [20091015-11:01:55.804438908] Processing File : iostat.001 [20091015-11:01:55.808240389] Discovered iostat_interval=[5] [20091015-11:01:56.595839145] Processing Directory : sar.breakout.001 [20091015-11:01:56.598011426] Discovered sar_interval=[5] [20091015-11:01:56.781907745] Processing File : mpstat.001 [20091015-11:01:56.784197929] Discovered mpstat_interval=[5] [20091015-11:01:57.935385747] Stopping profiling. [20091015-11:01:57.943094519] Killing daemon. [20091015-11:02:00.294702238] Processing File : oprofile.001 [20091015-11:02:00.297374402] Processing File : oprofile-brief.001 [20091015-11:02:02.174721895] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-10-15_0953/btrfs10-15' [20091015-11:02:06.586039062] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20091015-11:02:12.410923263] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20091015-11:02:12.598573548] 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 [20091015-11:02:12.651607177] 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' [20091015-11:02:12.701936579] new log requested [20091015-11:02:12.744845498] Running command ffsb [20091015-11:02:24.404200203] 10/15/2009-11:02:24 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb Succeeded [20091015-11:02:24.415146887] Importing argument : num_threads=128 [20091015-11:02:24.443420633] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20091015-11:02:24.538639653] FFSB version 6.0-RC2.1 started [20091015-11:02:24.540732724] [20091015-11:02:25.082907598] benchmark time = 300 [20091015-11:02:25.085351668] ThreadGroup 0 [20091015-11:02:25.087737365] ================ [20091015-11:02:25.090008882] num_threads = 128 [20091015-11:02:25.092263019] [20091015-11:02:25.094537205] read_random = off [20091015-11:02:25.096827159] read_size = 0 (0B) [20091015-11:02:25.098881530] read_blocksize = 0 (0B) [20091015-11:02:25.100848821] read_skip = off [20091015-11:02:25.102785914] read_skipsize = 0 (0B) [20091015-11:02:25.104788626] [20091015-11:02:25.106690468] write_random = on [20091015-11:02:25.108975671] write_size = 5242880 (5MB) [20091015-11:02:25.111089206] fsync_file = 0 [20091015-11:02:25.113189190] write_blocksize = 4096 (4KB) [20091015-11:02:25.115682036] wait time = 0 [20091015-11:02:25.117695220] [20091015-11:02:25.119920568] op weights [20091015-11:02:25.122764972] read = 0 (0.00%) [20091015-11:02:25.124927581] readall = 0 (0.00%) [20091015-11:02:25.127140717] write = 1 (100.00%) [20091015-11:02:25.129316219] create = 0 (0.00%) [20091015-11:02:25.131488878] append = 0 (0.00%) [20091015-11:02:25.133471986] delete = 0 (0.00%) [20091015-11:02:25.135599396] metaop = 0 (0.00%) [20091015-11:02:25.137743466] createdir = 0 (0.00%) [20091015-11:02:25.139651175] stat = 0 (0.00%) [20091015-11:02:25.141834753] writeall = 0 (0.00%) [20091015-11:02:25.143926973] writeall_fsync = 0 (0.00%) [20091015-11:02:25.145828915] open_close = 0 (0.00%) [20091015-11:02:25.148010621] write_fsync = 0 (0.00%) [20091015-11:02:25.150715615] create_fsync = 0 (0.00%) [20091015-11:02:25.153068879] append_fsync = 0 (0.00%) [20091015-11:02:25.155215120] [20091015-11:02:25.157984118] FileSystem /mnt/ffsb1 [20091015-11:02:25.159961840] ========== [20091015-11:02:25.162049885] num_dirs = 0 [20091015-11:02:25.164074085] starting files = 1024 [20091015-11:02:25.166401645] [20091015-11:02:25.168623333] min file size = 104857600 (100MB) [20091015-11:02:25.170819246] max file size = 104857600 (100MB) [20091015-11:02:25.173807163] directio = off [20091015-11:02:25.175980593] alignedio = on [20091015-11:02:25.178134877] bufferedio = off [20091015-11:02:25.180334925] [20091015-11:02:25.182427364] aging is off [20091015-11:02:25.184542568] current utilization = 5.14% [20091015-11:02:25.186954820] [20091015-11:02:25.189192756] creating new fileset /mnt/ffsb1 [20091015-11:18:54.164145439] fs setup took 988 secs [20091015-11:19:26.618443551] Syncing()...32 sec [20091015-11:19:26.621552127] Starting Actual Benchmark At: Thu Oct 15 11:19:26 2009 [20091015-11:19:26.663728931] [20091015-11:24:43.943798985] Syncing()...3 sec [20091015-11:24:43.991427514] FFSB benchmark finished at: Thu Oct 15 11:24:43 2009 [20091015-11:24:43.994458904] [20091015-11:24:43.997491008] Results: [20091015-11:24:44.068267446] Benchmark took 317.01 sec [20091015-11:24:44.070779151] [20091015-11:24:44.073489235] Total Results [20091015-11:24:44.092334256] =============== [20091015-11:24:44.096559482] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20091015-11:24:44.099941566] ======= ============ ========= ======= =========== ========== [20091015-11:24:44.103294183] write : 3855360 12161.46 100.000% 100.000% 47.5MB/sec [20091015-11:24:44.106180943] - [20091015-11:24:44.109266501] 12161.46 Transactions per Second [20091015-11:24:44.112025790] [20091015-11:24:44.114947955] Throughput Results [20091015-11:24:44.134014509] =================== [20091015-11:24:44.136409855] Write Throughput: 47.5MB/sec [20091015-11:24:44.139288081] [20091015-11:24:44.142055085] System Call Latency statistics in millisecs [20091015-11:24:44.144705189] ===== [20091015-11:24:44.149161094] Min Avg Max Total Calls [20091015-11:24:44.152018501] ======== ======== ======== ============ [20091015-11:24:44.154480951] [ open] 0.007000 1.859217 267.747009 3012 [20091015-11:24:44.157247412] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-11:24:44.159845374] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-11:24:44.162346567] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-11:24:44.164663344] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-11:24:44.167043205] msec_range[4] 200.000000 - 500.000000 : 18 [20091015-11:24:44.169461999] msec_range[5] 100.000000 - 200.000000 : 4 [20091015-11:24:44.171811437] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-11:24:44.174089549] msec_range[7] 20.000000 - 50.000000 : 1 [20091015-11:24:44.176905054] msec_range[8] 10.000000 - 20.000000 : 0 [20091015-11:24:44.180119509] msec_range[9] 5.000000 - 10.000000 : 1 [20091015-11:24:44.183241342] msec_range[10] 2.000000 - 5.000000 : 2 [20091015-11:24:44.185845240] msec_range[11] 1.000000 - 2.000000 : 2 [20091015-11:24:44.188417299] msec_range[12] 0.500000 - 1.000000 : 4 [20091015-11:24:44.190822907] msec_range[13] 0.200000 - 0.500000 : 207 [20091015-11:24:44.193113471] msec_range[14] 0.100000 - 0.200000 : 987 [20091015-11:24:44.195926016] msec_range[15] 0.050000 - 0.100000 : 422 [20091015-11:24:44.198868039] msec_range[16] 0.020000 - 0.050000 : 1263 [20091015-11:24:44.201867843] msec_range[17] 0.010000 - 0.020000 : 83 [20091015-11:24:44.204725115] msec_range[18] 0.000000 - 0.010000 : 18 [20091015-11:24:44.207983840] [20091015-11:24:44.211167559] [ write] 0.008000 9.666767 19727.029297 3855360 [20091015-11:24:44.213604982] msec_range[0] 5000.000000 - 10000.000000 : 1030 [20091015-11:24:44.216127883] msec_range[1] 2000.000000 - 5000.000000 : 7019 [20091015-11:24:44.218942465] msec_range[2] 1000.000000 - 2000.000000 : 3851 [20091015-11:24:44.221749025] msec_range[3] 500.000000 - 1000.000000 : 1581 [20091015-11:24:44.224196853] msec_range[4] 200.000000 - 500.000000 : 1893 [20091015-11:24:44.226944015] msec_range[5] 100.000000 - 200.000000 : 1076 [20091015-11:24:44.229863452] msec_range[6] 50.000000 - 100.000000 : 1020 [20091015-11:24:44.232570433] msec_range[7] 20.000000 - 50.000000 : 1990 [20091015-11:24:44.235583184] msec_range[8] 10.000000 - 20.000000 : 2055 [20091015-11:24:44.237985584] msec_range[9] 5.000000 - 10.000000 : 2839 [20091015-11:24:44.240716503] msec_range[10] 2.000000 - 5.000000 : 4203 [20091015-11:24:44.243747769] msec_range[11] 1.000000 - 2.000000 : 3672 [20091015-11:24:44.246940926] msec_range[12] 0.500000 - 1.000000 : 5163 [20091015-11:24:44.249632318] msec_range[13] 0.200000 - 0.500000 : 36766 [20091015-11:24:44.252413800] msec_range[14] 0.100000 - 0.200000 : 339009 [20091015-11:24:44.255718678] msec_range[15] 0.050000 - 0.100000 : 853472 [20091015-11:24:44.258704888] msec_range[16] 0.020000 - 0.050000 : 1587558 [20091015-11:24:44.261190493] msec_range[17] 0.010000 - 0.020000 : 1000766 [20091015-11:24:44.263638033] msec_range[18] 0.000000 - 0.010000 : 371 [20091015-11:24:44.266384619] [20091015-11:24:44.269250873] [ lseek] 0.000000 0.479689 16586.863281 3855360 [20091015-11:24:44.271687240] msec_range[0] 5000.000000 - 10000.000000 : 84 [20091015-11:24:44.274603728] msec_range[1] 2000.000000 - 5000.000000 : 240 [20091015-11:24:44.277297530] msec_range[2] 1000.000000 - 2000.000000 : 168 [20091015-11:24:44.281308332] msec_range[3] 500.000000 - 1000.000000 : 98 [20091015-11:24:44.283656880] msec_range[4] 200.000000 - 500.000000 : 68 [20091015-11:24:44.286096826] msec_range[5] 100.000000 - 200.000000 : 27 [20091015-11:24:44.289190707] msec_range[6] 50.000000 - 100.000000 : 22 [20091015-11:24:44.291940651] msec_range[7] 20.000000 - 50.000000 : 31 [20091015-11:24:44.294392121] msec_range[8] 10.000000 - 20.000000 : 37 [20091015-11:24:44.297092348] msec_range[9] 5.000000 - 10.000000 : 36 [20091015-11:24:44.300161735] msec_range[10] 2.000000 - 5.000000 : 41 [20091015-11:24:44.303011423] msec_range[11] 1.000000 - 2.000000 : 21 [20091015-11:24:44.305389501] msec_range[12] 0.500000 - 1.000000 : 24 [20091015-11:24:44.307952582] msec_range[13] 0.200000 - 0.500000 : 109 [20091015-11:24:44.310798573] msec_range[14] 0.100000 - 0.200000 : 1121 [20091015-11:24:44.313205215] msec_range[15] 0.050000 - 0.100000 : 5181 [20091015-11:24:44.315606176] msec_range[16] 0.020000 - 0.050000 : 57923 [20091015-11:24:44.318124782] msec_range[17] 0.010000 - 0.020000 : 45860 [20091015-11:24:44.320860000] msec_range[18] 0.000000 - 0.010000 : 3744257 [20091015-11:24:44.323189374] [20091015-11:24:44.325608904] [ close] 0.003000 0.011125 0.959000 3012 [20091015-11:24:44.328237192] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-11:24:44.331128521] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-11:24:44.333540125] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-11:24:44.335944716] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-11:24:44.338691282] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-11:24:44.341683901] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-11:24:44.344205169] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-11:24:44.346606596] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-11:24:44.349119655] msec_range[8] 10.000000 - 20.000000 : 0 [20091015-11:24:44.352057679] msec_range[9] 5.000000 - 10.000000 : 0 [20091015-11:24:44.366290680] msec_range[10] 2.000000 - 5.000000 : 0 [20091015-11:24:44.368697792] msec_range[11] 1.000000 - 2.000000 : 0 [20091015-11:24:44.371427537] msec_range[12] 0.500000 - 1.000000 : 1 [20091015-11:24:44.374373922] msec_range[13] 0.200000 - 0.500000 : 0 [20091015-11:24:44.376757559] msec_range[14] 0.100000 - 0.200000 : 0 [20091015-11:24:44.379096852] msec_range[15] 0.050000 - 0.100000 : 3 [20091015-11:24:44.382437826] msec_range[16] 0.020000 - 0.050000 : 100 [20091015-11:24:44.385268516] msec_range[17] 0.010000 - 0.020000 : 1509 [20091015-11:24:44.387724669] msec_range[18] 0.000000 - 0.010000 : 1399 [20091015-11:24:44.390127695] [20091015-11:24:44.392696978] [20091015-11:24:44.395495929] [20091015-11:24:44.397867217] [20091015-11:24:44.400219467] 3.2% User Time [20091015-11:24:44.402772271] 81.9% System Time [20091015-11:24:44.405809589] 85.1% CPU Utilization [20091015-11:24:44.408235505] Profilers reporting [20091015-11:25:30.671149649] Profilers postprocessing [20091015-11:25:30.990674223] Processing File : iostat.001 [20091015-11:25:30.993058395] Discovered iostat_interval=[5] [20091015-11:25:31.834418938] Processing Directory : sar.breakout.001 [20091015-11:25:31.836633984] Discovered sar_interval=[5] [20091015-11:25:32.015795203] Processing File : mpstat.001 [20091015-11:25:32.018299820] Discovered mpstat_interval=[5] [20091015-11:25:33.170220810] Stopping profiling. [20091015-11:25:33.175632705] Killing daemon. [20091015-11:25:34.474713045] Processing File : oprofile.001 [20091015-11:25:34.477077016] Processing File : oprofile-brief.001 [20091015-11:25:36.153396185] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-10-15_0953/btrfs10-15' [20091015-11:25:40.890512713] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20091015-11:25:46.204410016] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20091015-11:25:46.357775439] 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 [20091015-11:25:46.411224684] 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' [20091015-11:25:46.459403343] new log requested [20091015-11:25:46.492053402] Running command ffsb [20091015-11:25:58.119359903] 10/15/2009-11:25:58 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb Succeeded [20091015-11:25:58.130278292] Importing argument : num_threads=1 [20091015-11:25:58.159771070] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20091015-11:25:58.242512468] FFSB version 6.0-RC2.1 started [20091015-11:25:58.244857977] [20091015-11:25:58.247358282] benchmark time = 300 [20091015-11:25:58.249622912] ThreadGroup 0 [20091015-11:25:58.251768404] ================ [20091015-11:25:58.254005252] num_threads = 1 [20091015-11:25:58.256233461] [20091015-11:25:58.258487409] read_random = off [20091015-11:25:58.260787399] read_size = 0 (0B) [20091015-11:25:58.262882247] read_blocksize = 0 (0B) [20091015-11:25:58.264877550] read_skip = off [20091015-11:25:58.266810931] read_skipsize = 0 (0B) [20091015-11:25:58.268806278] [20091015-11:25:58.270712150] write_random = on [20091015-11:25:58.272670577] write_size = 5242880 (5MB) [20091015-11:25:58.274570581] fsync_file = 0 [20091015-11:25:58.276624671] write_blocksize = 4096 (4KB) [20091015-11:25:58.278826017] wait time = 0 [20091015-11:25:58.280808897] [20091015-11:25:58.282713440] op weights [20091015-11:25:58.284839981] read = 0 (0.00%) [20091015-11:25:58.286961512] readall = 0 (0.00%) [20091015-11:25:58.288975344] write = 1 (100.00%) [20091015-11:25:58.290861854] create = 0 (0.00%) [20091015-11:25:58.293020072] append = 0 (0.00%) [20091015-11:25:58.295011123] delete = 0 (0.00%) [20091015-11:25:58.296826428] metaop = 0 (0.00%) [20091015-11:25:58.298938962] createdir = 0 (0.00%) [20091015-11:25:58.301082334] stat = 0 (0.00%) [20091015-11:25:58.303053713] writeall = 0 (0.00%) [20091015-11:25:58.304954682] writeall_fsync = 0 (0.00%) [20091015-11:25:58.307104573] open_close = 0 (0.00%) [20091015-11:25:58.309079727] write_fsync = 0 (0.00%) [20091015-11:25:58.310952817] create_fsync = 0 (0.00%) [20091015-11:25:58.313087797] append_fsync = 0 (0.00%) [20091015-11:25:58.315283495] [20091015-11:25:58.317373262] FileSystem /mnt/ffsb1 [20091015-11:25:58.319631989] ========== [20091015-11:25:58.322434055] num_dirs = 0 [20091015-11:25:58.324701690] starting files = 1024 [20091015-11:25:58.326638234] [20091015-11:25:58.328693410] min file size = 104857600 (100MB) [20091015-11:25:58.330772701] max file size = 104857600 (100MB) [20091015-11:25:58.332658511] directio = on [20091015-11:25:58.334752740] alignedio = on [20091015-11:25:58.336798256] bufferedio = off [20091015-11:25:58.338882140] [20091015-11:25:58.340806101] aging is off [20091015-11:25:58.342997886] current utilization = 5.12% [20091015-11:25:58.345311293] [20091015-11:25:58.347245455] creating new fileset /mnt/ffsb1 [20091015-11:41:56.676998296] fs setup took 958 secs [20091015-11:42:37.350112081] Syncing()...40 sec [20091015-11:42:37.352566640] Starting Actual Benchmark At: Thu Oct 15 11:42:37 2009 [20091015-11:42:37.401766527] [20091015-11:47:39.837081462] Syncing()...1 sec [20091015-11:47:39.840796960] FFSB benchmark finished at: Thu Oct 15 11:47:39 2009 [20091015-11:47:39.844118767] [20091015-11:47:39.847496060] Results: [20091015-11:47:39.867586520] Benchmark took 302.49 sec [20091015-11:47:39.870676390] [20091015-11:47:39.873954627] Total Results [20091015-11:47:39.894357143] =============== [20091015-11:47:39.897789169] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20091015-11:47:39.901095275] ======= ============ ========= ======= =========== ========== [20091015-11:47:39.904228883] write : 660480 2183.50 100.000% 100.000% 8.53MB/sec [20091015-11:47:39.908124560] - [20091015-11:47:39.911315386] 2183.50 Transactions per Second [20091015-11:47:39.914858208] [20091015-11:47:39.918240763] Throughput Results [20091015-11:47:39.939365233] =================== [20091015-11:47:39.942794841] Write Throughput: 8.53MB/sec [20091015-11:47:39.946097678] [20091015-11:47:39.949122098] System Call Latency statistics in millisecs [20091015-11:47:39.952709863] ===== [20091015-11:47:39.956279404] Min Avg Max Total Calls [20091015-11:47:39.971029074] ======== ======== ======== ============ [20091015-11:47:39.975006470] [ open] 0.011000 0.029543 0.140000 516 [20091015-11:47:39.980559983] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-11:47:39.985107391] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-11:47:39.988700118] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-11:47:39.992156002] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-11:47:39.995760645] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-11:47:39.999320102] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-11:47:40.003037655] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-11:47:40.009889427] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-11:47:40.016905463] msec_range[8] 10.000000 - 20.000000 : 0 [20091015-11:47:40.020763416] msec_range[9] 5.000000 - 10.000000 : 0 [20091015-11:47:40.025268211] msec_range[10] 2.000000 - 5.000000 : 0 [20091015-11:47:40.028913302] msec_range[11] 1.000000 - 2.000000 : 0 [20091015-11:47:40.032541219] msec_range[12] 0.500000 - 1.000000 : 0 [20091015-11:47:40.036249529] msec_range[13] 0.200000 - 0.500000 : 0 [20091015-11:47:40.039576990] msec_range[14] 0.100000 - 0.200000 : 4 [20091015-11:47:40.046676151] msec_range[15] 0.050000 - 0.100000 : 78 [20091015-11:47:40.051539511] msec_range[16] 0.020000 - 0.050000 : 253 [20091015-11:47:40.055967141] msec_range[17] 0.010000 - 0.020000 : 181 [20091015-11:47:40.059325082] msec_range[18] 0.000000 - 0.010000 : 0 [20091015-11:47:40.063674560] [20091015-11:47:40.067079058] [ write] 0.335000 0.453256 400.726990 660480 [20091015-11:47:40.071086481] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-11:47:40.073783516] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-11:47:40.076515066] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-11:47:40.079555347] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-11:47:40.082754093] msec_range[4] 200.000000 - 500.000000 : 9 [20091015-11:47:40.085985283] msec_range[5] 100.000000 - 200.000000 : 3 [20091015-11:47:40.138862535] msec_range[6] 50.000000 - 100.000000 : 2 [20091015-11:47:40.142418540] msec_range[7] 20.000000 - 50.000000 : 12 [20091015-11:47:40.151063988] msec_range[8] 10.000000 - 20.000000 : 25 [20091015-11:47:40.154685954] msec_range[9] 5.000000 - 10.000000 : 62 [20091015-11:47:40.159160782] msec_range[10] 2.000000 - 5.000000 : 1349 [20091015-11:47:40.163258794] msec_range[11] 1.000000 - 2.000000 : 2071 [20091015-11:47:40.200793714] msec_range[12] 0.500000 - 1.000000 : 48926 [20091015-11:47:40.204416318] msec_range[13] 0.200000 - 0.500000 : 608021 [20091015-11:47:40.216722539] msec_range[14] 0.100000 - 0.200000 : 0 [20091015-11:47:40.221296326] msec_range[15] 0.050000 - 0.100000 : 0 [20091015-11:47:40.224381448] msec_range[16] 0.020000 - 0.050000 : 0 [20091015-11:47:40.227331767] msec_range[17] 0.010000 - 0.020000 : 0 [20091015-11:47:40.232119159] msec_range[18] 0.000000 - 0.010000 : 0 [20091015-11:47:40.236001718] [20091015-11:47:40.238932664] [ lseek] 0.000000 0.001343 2.939000 660480 [20091015-11:47:40.243261647] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-11:47:40.246856112] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-11:47:40.250139148] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-11:47:40.253419732] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-11:47:40.256748658] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-11:47:40.261800388] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-11:47:40.265110910] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-11:47:40.268711186] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-11:47:40.272346778] msec_range[8] 10.000000 - 20.000000 : 0 [20091015-11:47:40.275675126] msec_range[9] 5.000000 - 10.000000 : 0 [20091015-11:47:40.279000979] msec_range[10] 2.000000 - 5.000000 : 2 [20091015-11:47:40.282277904] msec_range[11] 1.000000 - 2.000000 : 0 [20091015-11:47:40.292424047] msec_range[12] 0.500000 - 1.000000 : 0 [20091015-11:47:40.296138649] msec_range[13] 0.200000 - 0.500000 : 0 [20091015-11:47:40.300012252] msec_range[14] 0.100000 - 0.200000 : 0 [20091015-11:47:40.303638070] msec_range[15] 0.050000 - 0.100000 : 3 [20091015-11:47:40.306958339] msec_range[16] 0.020000 - 0.050000 : 5 [20091015-11:47:40.310287047] msec_range[17] 0.010000 - 0.020000 : 101 [20091015-11:47:40.321853527] msec_range[18] 0.000000 - 0.010000 : 660369 [20091015-11:47:40.325012266] [20091015-11:47:40.329236657] [ close] 0.003000 0.006089 0.015000 516 [20091015-11:47:40.332608826] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-11:47:40.335444565] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-11:47:40.350664078] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-11:47:40.353717601] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-11:47:40.356672741] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-11:47:40.359232905] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-11:47:40.362265292] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-11:47:40.365215607] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-11:47:40.368041233] msec_range[8] 10.000000 - 20.000000 : 0 [20091015-11:47:40.374601854] msec_range[9] 5.000000 - 10.000000 : 0 [20091015-11:47:40.377745814] msec_range[10] 2.000000 - 5.000000 : 0 [20091015-11:47:40.380703990] msec_range[11] 1.000000 - 2.000000 : 0 [20091015-11:47:40.383453196] msec_range[12] 0.500000 - 1.000000 : 0 [20091015-11:47:40.385954157] msec_range[13] 0.200000 - 0.500000 : 0 [20091015-11:47:40.389305469] msec_range[14] 0.100000 - 0.200000 : 0 [20091015-11:47:40.392744774] msec_range[15] 0.050000 - 0.100000 : 0 [20091015-11:47:40.395904726] msec_range[16] 0.020000 - 0.050000 : 0 [20091015-11:47:40.399211487] msec_range[17] 0.010000 - 0.020000 : 18 [20091015-11:47:40.423003667] msec_range[18] 0.000000 - 0.010000 : 498 [20091015-11:47:40.425905125] [20091015-11:47:40.428524454] [20091015-11:47:40.431635744] [20091015-11:47:40.434455939] [20091015-11:47:40.437131635] 0.5% User Time [20091015-11:47:40.439648317] 13.4% System Time [20091015-11:47:40.458998823] 14.0% CPU Utilization [20091015-11:47:40.461993060] Profilers reporting [20091015-11:48:00.192126318] Profilers postprocessing [20091015-11:48:00.493549827] Processing File : iostat.001 [20091015-11:48:00.496040057] Discovered iostat_interval=[5] [20091015-11:48:01.276167320] Processing Directory : sar.breakout.001 [20091015-11:48:01.278470547] Discovered sar_interval=[5] [20091015-11:48:01.451053874] Processing File : mpstat.001 [20091015-11:48:01.453507120] Discovered mpstat_interval=[5] [20091015-11:48:02.607310773] Stopping profiling. [20091015-11:48:02.612535480] Killing daemon. [20091015-11:48:03.888402633] Processing File : oprofile.001 [20091015-11:48:03.890864898] Processing File : oprofile-brief.001 [20091015-11:48:05.443387026] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-10-15_0953/btrfs10-15' [20091015-11:48:09.519239407] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20091015-11:48:13.889986346] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20091015-11:48:14.083578129] 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 [20091015-11:48:14.136843470] 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' [20091015-11:48:14.186730360] new log requested [20091015-11:48:14.215821902] Running command ffsb [20091015-11:48:25.529064130] 10/15/2009-11:48:25 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb Succeeded [20091015-11:48:25.540541617] Importing argument : num_threads=16 [20091015-11:48:25.569854727] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20091015-11:48:25.684334952] FFSB version 6.0-RC2.1 started [20091015-11:48:25.686661390] [20091015-11:48:25.728451912] benchmark time = 300 [20091015-11:48:25.730465219] ThreadGroup 0 [20091015-11:48:25.732623480] ================ [20091015-11:48:25.734779757] num_threads = 16 [20091015-11:48:25.736856221] [20091015-11:48:25.739216643] read_random = off [20091015-11:48:25.741519820] read_size = 0 (0B) [20091015-11:48:25.743816248] read_blocksize = 0 (0B) [20091015-11:48:25.745870961] read_skip = off [20091015-11:48:25.747876214] read_skipsize = 0 (0B) [20091015-11:48:25.749794405] [20091015-11:48:25.751786156] write_random = on [20091015-11:48:25.753697254] write_size = 5242880 (5MB) [20091015-11:48:25.755688750] fsync_file = 0 [20091015-11:48:25.757570008] write_blocksize = 4096 (4KB) [20091015-11:48:25.759543754] wait time = 0 [20091015-11:48:25.761495387] [20091015-11:48:25.763464209] op weights [20091015-11:48:25.765361950] read = 0 (0.00%) [20091015-11:48:25.767322271] readall = 0 (0.00%) [20091015-11:48:25.769330530] write = 1 (100.00%) [20091015-11:48:25.771331072] create = 0 (0.00%) [20091015-11:48:25.773472001] append = 0 (0.00%) [20091015-11:48:25.775647621] delete = 0 (0.00%) [20091015-11:48:25.778976911] metaop = 0 (0.00%) [20091015-11:48:25.781261942] createdir = 0 (0.00%) [20091015-11:48:25.783636527] stat = 0 (0.00%) [20091015-11:48:25.785778551] writeall = 0 (0.00%) [20091015-11:48:25.787892309] writeall_fsync = 0 (0.00%) [20091015-11:48:25.789836139] open_close = 0 (0.00%) [20091015-11:48:25.792008750] write_fsync = 0 (0.00%) [20091015-11:48:25.794519815] create_fsync = 0 (0.00%) [20091015-11:48:25.796708367] append_fsync = 0 (0.00%) [20091015-11:48:25.799033349] [20091015-11:48:25.801933588] FileSystem /mnt/ffsb1 [20091015-11:48:25.804056872] ========== [20091015-11:48:25.806315602] num_dirs = 0 [20091015-11:48:25.809144862] starting files = 1024 [20091015-11:48:25.811385621] [20091015-11:48:25.813531499] min file size = 104857600 (100MB) [20091015-11:48:25.815693315] max file size = 104857600 (100MB) [20091015-11:48:25.818092947] directio = on [20091015-11:48:25.820139198] alignedio = on [20091015-11:48:25.822401435] bufferedio = off [20091015-11:48:25.824824346] [20091015-11:48:25.826835441] aging is off [20091015-11:48:25.828991271] current utilization = 4.59% [20091015-11:48:25.831587365] [20091015-11:48:25.833623619] creating new fileset /mnt/ffsb1 [20091015-11:53:35.692305698] fs setup took 309 secs [20091015-11:54:11.688608220] Syncing()...36 sec [20091015-11:54:11.692007413] Starting Actual Benchmark At: Thu Oct 15 11:54:11 2009 [20091015-11:54:11.731428569] [20091015-11:59:16.166620352] Syncing()...2 sec [20091015-11:59:16.170133251] FFSB benchmark finished at: Thu Oct 15 11:59:16 2009 [20091015-11:59:16.173788414] [20091015-11:59:16.177309366] Results: [20091015-11:59:16.197575549] Benchmark took 304.46 sec [20091015-11:59:16.201079521] [20091015-11:59:16.205470940] Total Results [20091015-11:59:16.225435833] =============== [20091015-11:59:16.229093059] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20091015-11:59:16.233436067] ======= ============ ========= ======= =========== ========== [20091015-11:59:16.236978429] write : 2539520 8340.97 100.000% 100.000% 32.6MB/sec [20091015-11:59:16.240352310] - [20091015-11:59:16.244281669] 8340.97 Transactions per Second [20091015-11:59:16.247512459] [20091015-11:59:16.250678128] Throughput Results [20091015-11:59:16.270853961] =================== [20091015-11:59:16.274161922] Write Throughput: 32.6MB/sec [20091015-11:59:16.277822999] [20091015-11:59:16.282414002] System Call Latency statistics in millisecs [20091015-11:59:16.292764508] ===== [20091015-11:59:16.298506991] Min Avg Max Total Calls [20091015-11:59:16.303176775] ======== ======== ======== ============ [20091015-11:59:16.306923114] [ open] 0.008000 0.045150 0.469000 1984 [20091015-11:59:16.311249606] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-11:59:16.315670369] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-11:59:16.319608431] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-11:59:16.322425566] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-11:59:16.326087185] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-11:59:16.329688043] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-11:59:16.335931320] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-11:59:16.339515757] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-11:59:16.344298638] msec_range[8] 10.000000 - 20.000000 : 0 [20091015-11:59:16.349524456] msec_range[9] 5.000000 - 10.000000 : 0 [20091015-11:59:16.375451342] msec_range[10] 2.000000 - 5.000000 : 0 [20091015-11:59:16.381330159] msec_range[11] 1.000000 - 2.000000 : 0 [20091015-11:59:16.385689776] msec_range[12] 0.500000 - 1.000000 : 0 [20091015-11:59:16.390591441] msec_range[13] 0.200000 - 0.500000 : 14 [20091015-11:59:16.397238529] msec_range[14] 0.100000 - 0.200000 : 166 [20091015-11:59:16.400869415] msec_range[15] 0.050000 - 0.100000 : 264 [20091015-11:59:16.404341743] msec_range[16] 0.020000 - 0.050000 : 1421 [20091015-11:59:16.408409323] msec_range[17] 0.010000 - 0.020000 : 112 [20091015-11:59:16.411452376] msec_range[18] 0.000000 - 0.010000 : 7 [20091015-11:59:16.417685858] [20091015-11:59:16.420925122] [ write] 0.357000 1.896486 687.945007 2539520 [20091015-11:59:16.424011928] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-11:59:16.427102481] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-11:59:16.431170708] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-11:59:16.434454036] msec_range[3] 500.000000 - 1000.000000 : 48 [20091015-11:59:16.438851287] msec_range[4] 200.000000 - 500.000000 : 194 [20091015-11:59:16.442191567] msec_range[5] 100.000000 - 200.000000 : 413 [20091015-11:59:16.444856890] msec_range[6] 50.000000 - 100.000000 : 2090 [20091015-11:59:16.450611770] msec_range[7] 20.000000 - 50.000000 : 3518 [20091015-11:59:16.453873222] msec_range[8] 10.000000 - 20.000000 : 8971 [20091015-11:59:16.459884455] msec_range[9] 5.000000 - 10.000000 : 83891 [20091015-11:59:16.463996730] msec_range[10] 2.000000 - 5.000000 : 562902 [20091015-11:59:16.467542570] msec_range[11] 1.000000 - 2.000000 : 1023442 [20091015-11:59:16.471907600] msec_range[12] 0.500000 - 1.000000 : 848420 [20091015-11:59:16.476157175] msec_range[13] 0.200000 - 0.500000 : 5631 [20091015-11:59:16.481107648] msec_range[14] 0.100000 - 0.200000 : 0 [20091015-11:59:16.484467818] msec_range[15] 0.050000 - 0.100000 : 0 [20091015-11:59:16.490550350] msec_range[16] 0.020000 - 0.050000 : 0 [20091015-11:59:16.494583092] msec_range[17] 0.010000 - 0.020000 : 0 [20091015-11:59:16.500277231] msec_range[18] 0.000000 - 0.010000 : 0 [20091015-11:59:16.503810882] [20091015-11:59:16.507985233] [ lseek] 0.000000 0.001942 7.477000 2539520 [20091015-11:59:16.518196198] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-11:59:16.522196755] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-11:59:16.526714594] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-11:59:16.530880354] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-11:59:16.534768288] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-11:59:16.539032856] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-11:59:16.542614837] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-11:59:16.546311828] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-11:59:16.550484489] msec_range[8] 10.000000 - 20.000000 : 0 [20091015-11:59:16.554172409] msec_range[9] 5.000000 - 10.000000 : 2 [20091015-11:59:16.557963894] msec_range[10] 2.000000 - 5.000000 : 2 [20091015-11:59:16.562365243] msec_range[11] 1.000000 - 2.000000 : 2 [20091015-11:59:16.565776799] msec_range[12] 0.500000 - 1.000000 : 3 [20091015-11:59:16.569091301] msec_range[13] 0.200000 - 0.500000 : 39 [20091015-11:59:16.572482180] msec_range[14] 0.100000 - 0.200000 : 395 [20091015-11:59:16.577628159] msec_range[15] 0.050000 - 0.100000 : 1017 [20091015-11:59:16.581597317] msec_range[16] 0.020000 - 0.050000 : 3904 [20091015-11:59:16.585236338] msec_range[17] 0.010000 - 0.020000 : 11781 [20091015-11:59:16.588807903] msec_range[18] 0.000000 - 0.010000 : 2522375 [20091015-11:59:16.592244768] [20091015-11:59:16.596007164] [ close] 0.003000 0.009575 0.060000 1984 [20091015-11:59:16.601303008] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-11:59:16.605067638] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-11:59:16.608652293] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-11:59:16.612730453] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-11:59:16.616079034] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-11:59:16.619296938] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-11:59:16.622560368] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-11:59:16.626083486] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-11:59:16.630396324] msec_range[8] 10.000000 - 20.000000 : 0 [20091015-11:59:16.633637170] msec_range[9] 5.000000 - 10.000000 : 0 [20091015-11:59:16.637350318] msec_range[10] 2.000000 - 5.000000 : 0 [20091015-11:59:16.640822413] msec_range[11] 1.000000 - 2.000000 : 0 [20091015-11:59:16.644041697] msec_range[12] 0.500000 - 1.000000 : 0 [20091015-11:59:16.647281723] msec_range[13] 0.200000 - 0.500000 : 0 [20091015-11:59:16.650310581] msec_range[14] 0.100000 - 0.200000 : 0 [20091015-11:59:16.653298246] msec_range[15] 0.050000 - 0.100000 : 2 [20091015-11:59:16.656227145] msec_range[16] 0.020000 - 0.050000 : 37 [20091015-11:59:16.659264897] msec_range[17] 0.010000 - 0.020000 : 600 [20091015-11:59:16.662186880] msec_range[18] 0.000000 - 0.010000 : 1345 [20091015-11:59:16.665233660] [20091015-11:59:16.668038968] [20091015-11:59:16.671262836] [20091015-11:59:16.674115010] [20091015-11:59:16.677081824] 2.8% User Time [20091015-11:59:16.679953282] 105.1% System Time [20091015-11:59:16.682911146] 107.9% CPU Utilization [20091015-11:59:16.685752331] Profilers reporting [20091015-11:59:38.165986629] Profilers postprocessing [20091015-11:59:38.389933623] Processing File : iostat.001 [20091015-11:59:38.392413076] Discovered iostat_interval=[5] [20091015-11:59:39.162123817] Processing Directory : sar.breakout.001 [20091015-11:59:39.164578157] Discovered sar_interval=[5] [20091015-11:59:39.336902801] Processing File : mpstat.001 [20091015-11:59:39.339295975] Discovered mpstat_interval=[5] [20091015-11:59:40.490625100] Stopping profiling. [20091015-11:59:40.495657351] Killing daemon. [20091015-11:59:41.780894474] Processing File : oprofile.001 [20091015-11:59:41.784237379] Processing File : oprofile-brief.001 [20091015-11:59:42.889945332] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-10-15_0953/btrfs10-15' [20091015-11:59:47.339809758] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20091015-11:59:52.816944966] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20091015-11:59:53.000611997] ONLY : Command [run random_writes_odirect__threads_0128 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb num_threads=128] found for me [20091015-11:59:53.054381069] PROCESSING COMMAND : 'run random_writes_odirect__threads_0128 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb num_threads=128' [20091015-11:59:53.103799559] new log requested [20091015-11:59:53.134886389] Running command ffsb [20091015-12:00:04.042312717] 10/15/2009-12:00:04 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb Succeeded [20091015-12:00:04.053883496] Importing argument : num_threads=128 [20091015-12:00:04.083295009] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20091015-12:00:04.176521503] FFSB version 6.0-RC2.1 started [20091015-12:00:04.178773597] [20091015-12:00:04.720273659] benchmark time = 300 [20091015-12:00:04.722493590] ThreadGroup 0 [20091015-12:00:04.724778105] ================ [20091015-12:00:04.726931230] num_threads = 128 [20091015-12:00:04.729092310] [20091015-12:00:04.731258984] read_random = off [20091015-12:00:04.733409687] read_size = 0 (0B) [20091015-12:00:04.735748891] read_blocksize = 0 (0B) [20091015-12:00:04.737825829] read_skip = off [20091015-12:00:04.739803552] read_skipsize = 0 (0B) [20091015-12:00:04.741762840] [20091015-12:00:04.743742235] write_random = on [20091015-12:00:04.745643402] write_size = 5242880 (5MB) [20091015-12:00:04.747617924] fsync_file = 0 [20091015-12:00:04.749515496] write_blocksize = 4096 (4KB) [20091015-12:00:04.751474646] wait time = 0 [20091015-12:00:04.753361598] [20091015-12:00:04.755395155] op weights [20091015-12:00:04.757285472] read = 0 (0.00%) [20091015-12:00:04.759330566] readall = 0 (0.00%) [20091015-12:00:04.761415142] write = 1 (100.00%) [20091015-12:00:04.763383848] create = 0 (0.00%) [20091015-12:00:04.765496884] append = 0 (0.00%) [20091015-12:00:04.767617987] delete = 0 (0.00%) [20091015-12:00:04.769703612] metaop = 0 (0.00%) [20091015-12:00:04.771635840] createdir = 0 (0.00%) [20091015-12:00:04.773744591] stat = 0 (0.00%) [20091015-12:00:04.775857836] writeall = 0 (0.00%) [20091015-12:00:04.777838610] writeall_fsync = 0 (0.00%) [20091015-12:00:04.779952620] open_close = 0 (0.00%) [20091015-12:00:04.782020645] write_fsync = 0 (0.00%) [20091015-12:00:04.784052417] create_fsync = 0 (0.00%) [20091015-12:00:04.786000215] append_fsync = 0 (0.00%) [20091015-12:00:04.788064281] [20091015-12:00:04.790109558] FileSystem /mnt/ffsb1 [20091015-12:00:04.792082677] ========== [20091015-12:00:04.793983726] num_dirs = 0 [20091015-12:00:04.795958797] starting files = 1024 [20091015-12:00:04.797866066] [20091015-12:00:04.799823747] min file size = 104857600 (100MB) [20091015-12:00:04.801723883] max file size = 104857600 (100MB) [20091015-12:00:04.803712061] directio = on [20091015-12:00:04.805634791] alignedio = on [20091015-12:00:04.807584201] bufferedio = off [20091015-12:00:04.809456018] [20091015-12:00:04.811425554] aging is off [20091015-12:00:04.813354113] current utilization = 4.90% [20091015-12:00:04.815335394] [20091015-12:00:04.817185973] creating new fileset /mnt/ffsb1 [20091015-12:11:49.839566363] fs setup took 705 secs [20091015-12:12:22.120502409] Syncing()...32 sec [20091015-12:12:22.125647761] Starting Actual Benchmark At: Thu Oct 15 12:12:22 2009 [20091015-12:12:22.153286927] [20091015-12:17:36.368225994] Syncing()...2 sec [20091015-12:17:36.371756069] FFSB benchmark finished at: Thu Oct 15 12:17:36 2009 [20091015-12:17:36.375062068] [20091015-12:17:36.378527065] Results: [20091015-12:17:36.399848214] Benchmark took 314.23 sec [20091015-12:17:36.403153274] [20091015-12:17:36.406268812] Total Results [20091015-12:17:36.427496696] =============== [20091015-12:17:36.430646628] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20091015-12:17:36.434092228] ======= ============ ========= ======= =========== ========== [20091015-12:17:36.437761021] write : 2621440 8342.44 100.000% 100.000% 32.6MB/sec [20091015-12:17:36.440912635] - [20091015-12:17:36.443733520] 8342.44 Transactions per Second [20091015-12:17:36.446817160] [20091015-12:17:36.450834262] Throughput Results [20091015-12:17:36.470525489] =================== [20091015-12:17:36.473914558] Write Throughput: 32.6MB/sec [20091015-12:17:36.477096086] [20091015-12:17:36.480319056] System Call Latency statistics in millisecs [20091015-12:17:36.483482095] ===== [20091015-12:17:36.486556058] Min Avg Max Total Calls [20091015-12:17:36.489994742] ======== ======== ======== ============ [20091015-12:17:36.494627615] [ open] 0.007000 0.079936 7.676000 2048 [20091015-12:17:36.499135746] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-12:17:36.508739829] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-12:17:36.517435187] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-12:17:36.541541792] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-12:17:36.546476664] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-12:17:36.550845533] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-12:17:36.554148866] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-12:17:36.557566647] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-12:17:36.560964395] msec_range[8] 10.000000 - 20.000000 : 0 [20091015-12:17:36.565389733] msec_range[9] 5.000000 - 10.000000 : 6 [20091015-12:17:36.572303374] msec_range[10] 2.000000 - 5.000000 : 0 [20091015-12:17:36.582328123] msec_range[11] 1.000000 - 2.000000 : 4 [20091015-12:17:36.589689446] msec_range[12] 0.500000 - 1.000000 : 1 [20091015-12:17:36.596440372] msec_range[13] 0.200000 - 0.500000 : 73 [20091015-12:17:36.604576586] msec_range[14] 0.100000 - 0.200000 : 230 [20091015-12:17:36.608331274] msec_range[15] 0.050000 - 0.100000 : 145 [20091015-12:17:36.617212552] msec_range[16] 0.020000 - 0.050000 : 1432 [20091015-12:17:36.620813563] msec_range[17] 0.010000 - 0.020000 : 137 [20091015-12:17:36.625523303] msec_range[18] 0.000000 - 0.010000 : 20 [20091015-12:17:36.632022763] [20091015-12:17:36.636319299] [ write] 0.389000 15.135044 792.093994 2621440 [20091015-12:17:36.641331069] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-12:17:36.645134452] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-12:17:36.648524615] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-12:17:36.652645594] msec_range[3] 500.000000 - 1000.000000 : 192 [20091015-12:17:36.655873657] msec_range[4] 200.000000 - 500.000000 : 1437 [20091015-12:17:36.658886750] msec_range[5] 100.000000 - 200.000000 : 6000 [20091015-12:17:36.661838509] msec_range[6] 50.000000 - 100.000000 : 39584 [20091015-12:17:36.664670116] msec_range[7] 20.000000 - 50.000000 : 580993 [20091015-12:17:36.667758834] msec_range[8] 10.000000 - 20.000000 : 928296 [20091015-12:17:36.671502632] msec_range[9] 5.000000 - 10.000000 : 608026 [20091015-12:17:36.679480684] msec_range[10] 2.000000 - 5.000000 : 322322 [20091015-12:17:36.684553546] msec_range[11] 1.000000 - 2.000000 : 119694 [20091015-12:17:36.690630920] msec_range[12] 0.500000 - 1.000000 : 14651 [20091015-12:17:36.695503912] msec_range[13] 0.200000 - 0.500000 : 245 [20091015-12:17:36.700415162] msec_range[14] 0.100000 - 0.200000 : 0 [20091015-12:17:36.704426751] msec_range[15] 0.050000 - 0.100000 : 0 [20091015-12:17:36.709567990] msec_range[16] 0.020000 - 0.050000 : 0 [20091015-12:17:36.713387679] msec_range[17] 0.010000 - 0.020000 : 0 [20091015-12:17:36.716550726] msec_range[18] 0.000000 - 0.010000 : 0 [20091015-12:17:36.719762704] [20091015-12:17:36.732769457] [ lseek] 0.000000 0.002334 7.567000 2621440 [20091015-12:17:36.735969612] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-12:17:36.746958263] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-12:17:36.757212790] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-12:17:36.760469447] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-12:17:36.764209165] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-12:17:36.769427428] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-12:17:36.773567796] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-12:17:36.777574871] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-12:17:36.780592775] msec_range[8] 10.000000 - 20.000000 : 0 [20091015-12:17:36.783906937] msec_range[9] 5.000000 - 10.000000 : 1 [20091015-12:17:36.787872296] msec_range[10] 2.000000 - 5.000000 : 2 [20091015-12:17:36.790602289] msec_range[11] 1.000000 - 2.000000 : 3 [20091015-12:17:36.794529001] msec_range[12] 0.500000 - 1.000000 : 6 [20091015-12:17:36.804494204] msec_range[13] 0.200000 - 0.500000 : 144 [20091015-12:17:36.810330424] msec_range[14] 0.100000 - 0.200000 : 1026 [20091015-12:17:36.814884840] msec_range[15] 0.050000 - 0.100000 : 1678 [20091015-12:17:36.817981010] msec_range[16] 0.020000 - 0.050000 : 3814 [20091015-12:17:36.821330748] msec_range[17] 0.010000 - 0.020000 : 24542 [20091015-12:17:36.826138430] msec_range[18] 0.000000 - 0.010000 : 2590224 [20091015-12:17:36.829554481] [20091015-12:17:36.832912572] [ close] 0.004000 0.010516 0.057000 2048 [20091015-12:17:36.837320735] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-12:17:36.840775851] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-12:17:36.845297536] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-12:17:36.848674375] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-12:17:36.851805465] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-12:17:36.855637046] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-12:17:36.858892493] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-12:17:36.862449403] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-12:17:36.865956261] msec_range[8] 10.000000 - 20.000000 : 0 [20091015-12:17:36.874034336] msec_range[9] 5.000000 - 10.000000 : 0 [20091015-12:17:36.877224341] msec_range[10] 2.000000 - 5.000000 : 0 [20091015-12:17:36.880515661] msec_range[11] 1.000000 - 2.000000 : 0 [20091015-12:17:36.883845844] msec_range[12] 0.500000 - 1.000000 : 0 [20091015-12:17:36.886786173] msec_range[13] 0.200000 - 0.500000 : 0 [20091015-12:17:36.889838993] msec_range[14] 0.100000 - 0.200000 : 0 [20091015-12:17:36.893086508] msec_range[15] 0.050000 - 0.100000 : 1 [20091015-12:17:36.897004652] msec_range[16] 0.020000 - 0.050000 : 74 [20091015-12:17:36.900374585] msec_range[17] 0.010000 - 0.020000 : 895 [20091015-12:17:36.903769425] msec_range[18] 0.000000 - 0.010000 : 1078 [20091015-12:17:36.909519333] [20091015-12:17:36.912875725] [20091015-12:17:36.916117470] [20091015-12:17:36.919617104] [20091015-12:17:36.923318021] 3.5% User Time [20091015-12:17:36.926746911] 151.2% System Time [20091015-12:17:36.929910582] 154.7% CPU Utilization [20091015-12:17:36.933826618] Profilers reporting [20091015-12:18:05.152630733] Profilers postprocessing [20091015-12:18:05.475541476] Processing File : iostat.001 [20091015-12:18:05.477716263] Discovered iostat_interval=[5] [20091015-12:18:06.248612239] Processing Directory : sar.breakout.001 [20091015-12:18:06.250933674] Discovered sar_interval=[5] [20091015-12:18:06.426261654] Processing File : mpstat.001 [20091015-12:18:06.428595431] Discovered mpstat_interval=[5] [20091015-12:18:07.579835199] Stopping profiling. [20091015-12:18:07.584597521] Killing daemon. [20091015-12:18:08.872834801] Processing File : oprofile.001 [20091015-12:18:08.875142244] Processing File : oprofile-brief.001 [20091015-12:18:11.421347158] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-10-15_0953/btrfs10-15' [20091015-12:18:15.775501426] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20091015-12:18:22.471574208] PROCESSING COMMAND : 'mkfs.btrfs /dev/ffsbdev1' [20091015-12:18:22.513396692] [20091015-12:18:22.515696710] WARNING! - Btrfs v0.18-13-gb8420fa IS EXPERIMENTAL [20091015-12:18:22.517960684] WARNING! - see http://btrfs.wiki.kernel.org before using [20091015-12:18:22.520325302] [20091015-12:18:22.522594243] fs created label (null) on /dev/ffsbdev1 [20091015-12:18:22.525085488] nodesize 4096 leafsize 4096 sectorsize 4096 size 2.18TB [20091015-12:18:22.527460992] Btrfs v0.18-13-gb8420fa [20091015-12:18:22.584581729] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20091015-12:18:22.661023197] ONLY : Command [run large_file_creates__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/large_file_creates.ffsb num_threads=1] found for me [20091015-12:18:22.714909581] PROCESSING COMMAND : 'run large_file_creates__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/large_file_creates.ffsb num_threads=1' [20091015-12:18:22.763706013] new log requested [20091015-12:18:22.794342013] Running command ffsb [20091015-12:18:34.147325413] 10/15/2009-12:18:34 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/large_file_creates.ffsb Succeeded [20091015-12:18:34.158682953] Importing argument : num_threads=1 [20091015-12:18:34.188247161] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20091015-12:18:34.282379584] FFSB version 6.0-RC2.1 started [20091015-12:18:34.284793747] [20091015-12:18:34.287302389] benchmark time = 300 [20091015-12:18:34.289543674] ThreadGroup 0 [20091015-12:18:34.291812980] ================ [20091015-12:18:34.294117406] num_threads = 1 [20091015-12:18:34.296273941] [20091015-12:18:34.298515628] read_random = off [20091015-12:18:34.300733548] read_size = 0 (0B) [20091015-12:18:34.302734509] read_blocksize = 0 (0B) [20091015-12:18:34.304770882] read_skip = off [20091015-12:18:34.306732838] read_skipsize = 0 (0B) [20091015-12:18:34.308725143] [20091015-12:18:34.310632344] write_random = off [20091015-12:18:34.312614717] write_size = 0 (0B) [20091015-12:18:34.314510415] fsync_file = 0 [20091015-12:18:34.316477997] write_blocksize = 4096 (4KB) [20091015-12:18:34.318371895] wait time = 0 [20091015-12:18:34.320344505] [20091015-12:18:34.322241017] op weights [20091015-12:18:34.324208007] read = 0 (0.00%) [20091015-12:18:34.326081140] readall = 0 (0.00%) [20091015-12:18:34.328028504] write = 0 (0.00%) [20091015-12:18:34.329907807] create = 1 (100.00%) [20091015-12:18:34.331859817] append = 0 (0.00%) [20091015-12:18:34.333739594] delete = 0 (0.00%) [20091015-12:18:34.335686574] metaop = 0 (0.00%) [20091015-12:18:34.337540459] createdir = 0 (0.00%) [20091015-12:18:34.339476984] stat = 0 (0.00%) [20091015-12:18:34.341349287] writeall = 0 (0.00%) [20091015-12:18:34.343329133] writeall_fsync = 0 (0.00%) [20091015-12:18:34.345200139] open_close = 0 (0.00%) [20091015-12:18:34.347164145] write_fsync = 0 (0.00%) [20091015-12:18:34.349048176] create_fsync = 0 (0.00%) [20091015-12:18:34.350994856] append_fsync = 0 (0.00%) [20091015-12:18:34.352886128] [20091015-12:18:34.354843666] FileSystem /mnt/ffsb1 [20091015-12:18:34.356725259] ========== [20091015-12:18:34.358691280] num_dirs = 0 [20091015-12:18:34.360552018] starting files = 0 [20091015-12:18:34.362522158] [20091015-12:18:34.364383892] min file size = 1073741824 (1GB) [20091015-12:18:34.366341043] max file size = 1073741824 (1GB) [20091015-12:18:34.368209821] directio = off [20091015-12:18:34.370158744] alignedio = on [20091015-12:18:34.372038046] bufferedio = off [20091015-12:18:34.373973795] [20091015-12:18:34.375829602] aging is off [20091015-12:18:34.377761174] current utilization = 0.00% [20091015-12:18:34.379614859] [20091015-12:18:34.381575628] creating new fileset /mnt/ffsb1 [20091015-12:18:34.383442239] fs setup took 0 secs [20091015-12:18:35.063061128] Syncing()...0 sec [20091015-12:18:35.065290586] Starting Actual Benchmark At: Thu Oct 15 12:18:35 2009 [20091015-12:18:35.080556580] [20091015-12:23:42.159293111] Syncing()...2 sec [20091015-12:23:42.163138445] FFSB benchmark finished at: Thu Oct 15 12:23:42 2009 [20091015-12:23:42.166029626] [20091015-12:23:42.169566513] Results: [20091015-12:23:42.191213117] Benchmark took 307.02 sec [20091015-12:23:42.193710818] [20091015-12:23:42.196569325] Total Results [20091015-12:23:42.216155703] =============== [20091015-12:23:42.219365280] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20091015-12:23:42.224269111] ======= ============ ========= ======= =========== ========== [20091015-12:23:42.228970764] create : 21757952 70868.72 100.000% 100.000% 277MB/sec [20091015-12:23:42.231752949] - [20091015-12:23:42.234552205] 70868.72 Transactions per Second [20091015-12:23:42.237153241] [20091015-12:23:42.240562810] Throughput Results [20091015-12:23:42.257361021] =================== [20091015-12:23:42.260198143] Write Throughput: 277MB/sec [20091015-12:23:42.263679886] [20091015-12:23:42.267153830] System Call Latency statistics in millisecs [20091015-12:23:42.270245646] ===== [20091015-12:23:42.273146358] Min Avg Max Total Calls [20091015-12:23:42.276255561] ======== ======== ======== ============ [20091015-12:23:42.279045350] [ open] 0.098000 0.341410 3.654000 83 [20091015-12:23:42.282739471] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-12:23:42.290709936] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-12:23:42.293382237] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-12:23:42.299178592] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-12:23:42.302194857] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-12:23:42.305384670] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-12:23:42.308207854] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-12:23:42.311550404] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-12:23:42.314844390] msec_range[8] 10.000000 - 20.000000 : 0 [20091015-12:23:42.318139891] msec_range[9] 5.000000 - 10.000000 : 0 [20091015-12:23:42.321848341] msec_range[10] 2.000000 - 5.000000 : 1 [20091015-12:23:42.325021683] msec_range[11] 1.000000 - 2.000000 : 7 [20091015-12:23:42.337083248] msec_range[12] 0.500000 - 1.000000 : 4 [20091015-12:23:42.340761362] msec_range[13] 0.200000 - 0.500000 : 15 [20091015-12:23:42.344676061] msec_range[14] 0.100000 - 0.200000 : 55 [20091015-12:23:42.348052760] msec_range[15] 0.050000 - 0.100000 : 1 [20091015-12:23:42.351132845] msec_range[16] 0.020000 - 0.050000 : 0 [20091015-12:23:42.354065612] msec_range[17] 0.010000 - 0.020000 : 0 [20091015-12:23:42.356718381] msec_range[18] 0.000000 - 0.010000 : 0 [20091015-12:23:42.359191548] [20091015-12:23:42.362169713] [ write] 0.004000 0.013544 382.838989 21757952 [20091015-12:23:42.365549446] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-12:23:42.368909258] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-12:23:42.377504008] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-12:23:42.381456211] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-12:23:42.384502282] msec_range[4] 200.000000 - 500.000000 : 4 [20091015-12:23:42.387596582] msec_range[5] 100.000000 - 200.000000 : 1 [20091015-12:23:42.400472187] msec_range[6] 50.000000 - 100.000000 : 2 [20091015-12:23:42.411412734] msec_range[7] 20.000000 - 50.000000 : 34 [20091015-12:23:42.416955607] msec_range[8] 10.000000 - 20.000000 : 72 [20091015-12:23:42.420263179] msec_range[9] 5.000000 - 10.000000 : 546 [20091015-12:23:42.423879559] msec_range[10] 2.000000 - 5.000000 : 4356 [20091015-12:23:42.427416082] msec_range[11] 1.000000 - 2.000000 : 2199 [20091015-12:23:42.430930221] msec_range[12] 0.500000 - 1.000000 : 1415 [20091015-12:23:42.434342189] msec_range[13] 0.200000 - 0.500000 : 5195 [20091015-12:23:42.441249723] msec_range[14] 0.100000 - 0.200000 : 10515 [20091015-12:23:42.446419849] msec_range[15] 0.050000 - 0.100000 : 57597 [20091015-12:23:42.449613710] msec_range[16] 0.020000 - 0.050000 : 2310343 [20091015-12:23:42.452375530] msec_range[17] 0.010000 - 0.020000 : 9298913 [20091015-12:23:42.455978412] msec_range[18] 0.000000 - 0.010000 : 10066760 [20091015-12:23:42.459587282] [20091015-12:23:42.462207707] [ close] 0.008000 0.011735 0.024000 83 [20091015-12:23:42.467406509] msec_range[0] 5000.000000 - 10000.000000 : 0 [20091015-12:23:42.470137117] msec_range[1] 2000.000000 - 5000.000000 : 0 [20091015-12:23:42.472718210] msec_range[2] 1000.000000 - 2000.000000 : 0 [20091015-12:23:42.476011078] msec_range[3] 500.000000 - 1000.000000 : 0 [20091015-12:23:42.479856094] msec_range[4] 200.000000 - 500.000000 : 0 [20091015-12:23:42.482541528] msec_range[5] 100.000000 - 200.000000 : 0 [20091015-12:23:42.485697370] msec_range[6] 50.000000 - 100.000000 : 0 [20091015-12:23:42.488440484] msec_range[7] 20.000000 - 50.000000 : 0 [20091015-12:23:42.491181956] msec_range[8] 10.000000 - 20.000000 : 0 [20091015-12:23:42.493790915] msec_range[9] 5.000000 - 10.000000 : 0 [20091015-12:23:42.496756125] msec_range[10] 2.000000 - 5.000000 : 0 [20091015-12:23:42.499332470] msec_range[11] 1.000000 - 2.000000 : 0 [20091015-12:23:42.506287854] msec_range[12] 0.500000 - 1.000000 : 0 [20091015-12:23:42.526456471] msec_range[13] 0.200000 - 0.500000 : 0 [20091015-12:23:42.530312600] msec_range[14] 0.100000 - 0.200000 : 0 [20091015-12:23:42.534704529] msec_range[15] 0.050000 - 0.100000 : 0 [20091015-12:23:42.538743891] msec_range[16] 0.020000 - 0.050000 : 2 [20091015-12:23:42.541625716] msec_range[17] 0.010000 - 0.020000 : 56 [20091015-12:23:42.544980775] msec_range[18] 0.000000 - 0.010000 : 25 [20091015-12:23:42.547635374] [20091015-12:23:42.552047167] [20091015-12:23:42.555224364] [20091015-12:23:42.559787585] [20091015-12:23:42.563050318] 6.5% User Time [20091015-12:23:42.566842882] 83.9% System Time [20091015-12:23:42.570135365] 90.4% CPU Utilization [20091015-12:23:42.575171743] Profilers reporting [20091015-12:24:28.926184738] Profilers postprocessing [20091015-12:24:29.155540922] Processing File : iostat.001 [20091015-12:24:29.158127254] Discovered iostat_interval=[5] [20091015-12:24:29.957426259] Processing Directory : sar.breakout.001 [20091015-12:24:29.959688642] Discovered sar_interval=[5] [20091015-12:24:30.133503281] Processing File : mpstat.001 [20091015-12:24:30.139903645] Discovered mpstat_interval=[5] [20091015-12:24:31.289044809] Stopping profiling. [20091015-12:24:31.296603572] Killing daemon. [20091015-12:24:32.583544448] Processing File : oprofile.001 [20091015-12:24:32.586021805] Processing File : oprofile-brief.001 [20091015-12:24:33.999606614] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-10-15_0953/btrfs10-15'