[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'