[20090313-12:59:45.948446357] PROCESSING COMMAND : 'boot autobench' [20090313-12:59:46.364082695] Normal exit from autorun, probably reboot [20090313-13:04:25.336018310] PROCESSING COMMAND : 'clearprofilers' [20090313-13:04:25.719039415] PROCESSING COMMAND : 'useprofiler iostat 5' [20090313-13:04:25.832045642] Checking for sar... [20090313-13:04:25.835045807] found [20090313-13:04:25.982053908] PROCESSING COMMAND : 'useprofiler sar 5' [20090313-13:04:26.125061789] Checking for sar... [20090313-13:04:26.164063938] found [20090313-13:04:26.313072149] PROCESSING COMMAND : 'useprofiler mpstat 5' [20090313-13:04:26.427078431] Checking for sar... [20090313-13:04:26.429078541] found [20090313-13:04:26.654090940] PROCESSING COMMAND : 'useprofiler oprofile' [20090313-13:04:26.854101960] Checking for gettext... [20090313-13:04:26.882103504] found [20090313-13:04:26.884103614] Checking for libiberty in autobench... [20090313-13:04:26.942106810] found [20090313-13:04:26.945106975] Checking for popt... [20090313-13:04:26.947107085] found [20090313-13:04:26.950107250] Checking for popt64... [20090313-13:04:26.952107362] found [20090313-13:04:26.954107472] Checking for oprofile... [20090313-13:04:27.027111494] found [20090313-13:04:27.126116950] opcontrol: oprofile 0.9.4 compiled on Nov 19 2008 09:09:21 [20090313-13:04:27.478136346] dump fail: daemon died during last run ? [20090313-13:04:27.483136623] Detected stale lock file. Removing. [20090313-13:05:26.074635896] OPROFILE : using callgraph [5] [20090313-13:05:26.301892762] Daemon not running [20090313-13:05:26.304050397] Separate options: none [20090313-13:05:26.306468368] vmlinux file: /boot/vmlinux-2.6.29-rc3-autokern1 [20090313-13:05:26.308486677] Image filter: none [20090313-13:05:26.310641258] Call-graph depth: 5 [20090313-13:05:26.524768503] PROCESSING COMMAND : 'umount /mnt/ffsb1 > /dev/null 2>&1' [20090313-13:05:26.599819762] PROCESSING COMMAND : 'set-sched noop' [20090313-13:05:26.917612035] PROCESSING COMMAND : 'mkresultdirs hks.austin.ibm.com benchmarks/results/btrfs/ffsb btrfs2 2009-03-13_1304 btrfs-baseline' [20090313-13:05:27.124417772] Connecting to hks.austin.ibm.com... [20090313-13:05:27.126784402] Remote working directory: /opt [20090313-13:05:27.129137068] Remote working directory: /opt/benchmarks/results/btrfs/ffsb [20090313-13:05:27.131167099] Couldn't create directory: Failure [20090313-13:05:27.133464792] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs2 [20090313-13:05:27.135670037] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs2 [20090313-13:05:27.137707984] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs2/2009-03-13_1304 [20090313-13:05:27.139652473] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs2/2009-03-13_1304 [20090313-13:05:27.141594672] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs2/2009-03-13_1304/btrfs-baseline [20090313-13:05:27.212424357] PROCESSING COMMAND : 'mkfs.btrfs 2>&1' [20090313-13:05:27.239199001] usage: mkfs.btrfs [options] dev [ dev ... ] [20090313-13:05:27.241614991] options: [20090313-13:05:27.243846234] -b --byte-count total number of bytes in the FS [20090313-13:05:27.245914698] -l --leafsize size of btree leaves [20090313-13:05:27.248237341] -n --nodesize size of btree leaves [20090313-13:05:27.250285721] -s --sectorsize min block allocation [20090313-13:05:27.252310541] Btrfs v0.16-28-gb238b4b [20090313-13:05:27.337412660] PROCESSING COMMAND : 'mkfs.btrfs /dev/ffsbdev1' [20090313-13:05:27.375449573] fs created label (null) on /dev/ffsbdev1 [20090313-13:05:27.377629891] nodesize 4096 leafsize 4096 sectorsize 4096 size 68.37GB [20090313-13:05:27.379913554] Btrfs v0.16-28-gb238b4b [20090313-13:05:27.624140290] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090313-13:05:27.960391242] PROCESSING COMMAND : 'run sequential_reads__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb num_threads=1' [20090313-13:05:28.022748228] new log requested [20090313-13:05:28.056784939] Running command ffsb [20090313-13:05:36.183297952] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb [20090313-13:05:36.203263593] Importing argument : num_threads=1 [20090313-13:05:36.229237573] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090313-13:05:36.339701614] FFSB version 6.0-RC2.1 started [20090313-13:05:36.342019372] [20090313-13:05:36.344202817] benchmark time = 300 [20090313-13:05:36.346301111] ThreadGroup 0 [20090313-13:05:36.348499119] ================ [20090313-13:05:36.350609799] num_threads = 1 [20090313-13:05:36.352681836] [20090313-13:05:36.354719105] read_random = off [20090313-13:05:36.356771596] read_size = 0 (0B) [20090313-13:05:36.358889718] read_blocksize = 4096 (4KB) [20090313-13:05:36.360793408] read_skip = off [20090313-13:05:36.362998653] read_skipsize = 0 (0B) [20090313-13:05:36.364967490] [20090313-13:05:36.367019229] write_random = off [20090313-13:05:36.369074860] write_size = 0 (0B) [20090313-13:05:36.371009239] fsync_file = 0 [20090313-13:05:36.373039119] write_blocksize = 0 (0B) [20090313-13:05:36.374980519] wait time = 0 [20090313-13:05:36.376958153] [20090313-13:05:36.378906841] op weights [20090313-13:05:36.380746293] read = 0 (0.00%) [20090313-13:05:36.382735104] readall = 1 (100.00%) [20090313-13:05:36.384693306] write = 0 (0.00%) [20090313-13:05:36.386589308] create = 0 (0.00%) [20090313-13:05:36.388552933] append = 0 (0.00%) [20090313-13:05:36.390503615] delete = 0 (0.00%) [20090313-13:05:36.392385263] metaop = 0 (0.00%) [20090313-13:05:36.394357337] createdir = 0 (0.00%) [20090313-13:05:36.396327514] stat = 0 (0.00%) [20090313-13:05:36.398214740] writeall = 0 (0.00%) [20090313-13:05:36.400198755] writeall_fsync = 0 (0.00%) [20090313-13:05:36.402133953] open_close = 0 (0.00%) [20090313-13:05:36.403990545] write_fsync = 0 (0.00%) [20090313-13:05:36.405946323] create_fsync = 0 (0.00%) [20090313-13:05:36.407870980] append_fsync = 0 (0.00%) [20090313-13:05:36.409741870] [20090313-13:05:36.411714670] FileSystem /mnt/ffsb1 [20090313-13:05:36.413691020] ========== [20090313-13:05:36.415564390] num_dirs = 0 [20090313-13:05:36.417513265] starting files = 1024 [20090313-13:05:36.419454331] [20090313-13:05:36.421320696] min file size = 36700160 (35MB) [20090313-13:05:36.423279857] max file size = 36700160 (35MB) [20090313-13:05:36.425302047] directio = off [20090313-13:05:36.427376506] alignedio = on [20090313-13:05:36.429269496] bufferedio = off [20090313-13:05:36.431232992] [20090313-13:05:36.433164523] aging is off [20090313-13:05:36.435159078] current utilization = 0.00% [20090313-13:05:36.437104691] [20090313-13:05:36.438983048] checking existing fs: /mnt/ffsb1 [20090313-13:05:36.440945213] opendir: No such file or directory [20090313-13:05:36.442891872] recreating new fileset [20090313-13:12:03.612435328] fs setup took 386 secs [20090313-13:12:07.189311376] Syncing()...3 sec [20090313-13:12:07.198985092] Starting Actual Benchmark At: Fri Mar 13 13:12:07 2009 [20090313-13:12:07.234118948] [20090313-13:17:08.945894204] Syncing()...0 sec [20090313-13:17:09.033762485] FFSB benchmark finished at: Fri Mar 13 13:17:08 2009 [20090313-13:17:09.037140004] [20090313-13:17:09.040316147] Results: [20090313-13:17:09.065396843] Benchmark took 301.39 sec [20090313-13:17:09.068603283] [20090313-13:17:09.071496075] Total Results [20090313-13:17:09.088468854] =============== [20090313-13:17:09.091569522] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090313-13:17:09.094339984] ======= ============ ========= ======= =========== ========== [20090313-13:17:09.097136976] readall : 7060480 23426.43 100.000% 100.000% 91.5MB/sec [20090313-13:17:09.106711613] - [20090313-13:17:09.109679703] 23426.43 Transactions per Second [20090313-13:17:09.112441960] [20090313-13:17:09.114978262] Throughput Results [20090313-13:17:09.131393242] =================== [20090313-13:17:09.133913383] Read Throughput: 91.5MB/sec [20090313-13:17:09.136662120] [20090313-13:17:09.139255646] System Call Latency statistics in millisecs [20090313-13:17:09.142025399] ===== [20090313-13:17:09.144666750] Min Avg Max Total Calls [20090313-13:17:09.147315755] ======== ======== ======== ============ [20090313-13:17:09.149852872] [ open] 0.014000 0.544761 17.224001 788 [20090313-13:17:09.152430378] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090313-13:17:09.155018958] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090313-13:17:09.157581732] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090313-13:17:09.160339834] msec_range[3] 500.000000 - 1000.000000 : 0 [20090313-13:17:09.162904105] msec_range[4] 200.000000 - 500.000000 : 0 [20090313-13:17:09.165463807] msec_range[5] 100.000000 - 200.000000 : 0 [20090313-13:17:09.167896290] msec_range[6] 50.000000 - 100.000000 : 0 [20090313-13:17:09.170464599] msec_range[7] 20.000000 - 50.000000 : 0 [20090313-13:17:09.172943947] msec_range[8] 10.000000 - 20.000000 : 20 [20090313-13:17:09.175501962] msec_range[9] 5.000000 - 10.000000 : 13 [20090313-13:17:09.177973027] msec_range[10] 2.000000 - 5.000000 : 8 [20090313-13:17:09.180477036] msec_range[11] 1.000000 - 2.000000 : 0 [20090313-13:17:09.182917623] msec_range[12] 0.500000 - 1.000000 : 0 [20090313-13:17:09.185473851] msec_range[13] 0.200000 - 0.500000 : 1 [20090313-13:17:09.187916148] msec_range[14] 0.100000 - 0.200000 : 0 [20090313-13:17:09.190507522] msec_range[15] 0.050000 - 0.100000 : 62 [20090313-13:17:09.192955505] msec_range[16] 0.020000 - 0.050000 : 680 [20090313-13:17:09.195559146] msec_range[17] 0.010000 - 0.020000 : 4 [20090313-13:17:09.197979724] msec_range[18] 0.000000 - 0.010000 : 0 [20090313-13:17:09.200466524] [20090313-13:17:09.202848614] [ read] 0.001000 0.042330 157.615005 7060480 [20090313-13:17:09.205347866] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090313-13:17:09.207923039] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090313-13:17:09.210298097] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090313-13:17:09.212738962] msec_range[3] 500.000000 - 1000.000000 : 0 [20090313-13:17:09.215230926] msec_range[4] 200.000000 - 500.000000 : 0 [20090313-13:17:09.217673574] msec_range[5] 100.000000 - 200.000000 : 6 [20090313-13:17:09.220156441] msec_range[6] 50.000000 - 100.000000 : 534 [20090313-13:17:09.222580920] msec_range[7] 20.000000 - 50.000000 : 727 [20090313-13:17:09.225103184] msec_range[8] 10.000000 - 20.000000 : 2116 [20090313-13:17:09.227546273] msec_range[9] 5.000000 - 10.000000 : 7361 [20090313-13:17:09.230036019] msec_range[10] 2.000000 - 5.000000 : 28507 [20090313-13:17:09.232433760] msec_range[11] 1.000000 - 2.000000 : 1604 [20090313-13:17:09.234912209] msec_range[12] 0.500000 - 1.000000 : 554 [20090313-13:17:09.237313522] msec_range[13] 0.200000 - 0.500000 : 331 [20090313-13:17:09.239837861] msec_range[14] 0.100000 - 0.200000 : 821 [20090313-13:17:09.242219140] msec_range[15] 0.050000 - 0.100000 : 1469 [20090313-13:17:09.244721730] msec_range[16] 0.020000 - 0.050000 : 1416 [20090313-13:17:09.247095806] msec_range[17] 0.010000 - 0.020000 : 82720 [20090313-13:17:09.250512777] msec_range[18] 0.000000 - 0.010000 : 6932314 [20090313-13:17:09.253149923] [20090313-13:17:09.255715275] [ close] 0.006000 0.006475 0.013000 788 [20090313-13:17:09.258439618] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090313-13:17:09.261134693] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090313-13:17:09.263845686] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090313-13:17:09.266299346] msec_range[3] 500.000000 - 1000.000000 : 0 [20090313-13:17:09.268963901] msec_range[4] 200.000000 - 500.000000 : 0 [20090313-13:17:09.271506352] msec_range[5] 100.000000 - 200.000000 : 0 [20090313-13:17:09.274126190] msec_range[6] 50.000000 - 100.000000 : 0 [20090313-13:17:09.276998604] msec_range[7] 20.000000 - 50.000000 : 0 [20090313-13:17:09.279893908] msec_range[8] 10.000000 - 20.000000 : 0 [20090313-13:17:09.284480628] msec_range[9] 5.000000 - 10.000000 : 0 [20090313-13:17:09.287305585] msec_range[10] 2.000000 - 5.000000 : 0 [20090313-13:17:09.290050977] msec_range[11] 1.000000 - 2.000000 : 0 [20090313-13:17:09.292746073] msec_range[12] 0.500000 - 1.000000 : 0 [20090313-13:17:09.295568415] msec_range[13] 0.200000 - 0.500000 : 0 [20090313-13:17:09.298406374] msec_range[14] 0.100000 - 0.200000 : 0 [20090313-13:17:09.301320967] msec_range[15] 0.050000 - 0.100000 : 0 [20090313-13:17:09.304172824] msec_range[16] 0.020000 - 0.050000 : 0 [20090313-13:17:09.306960712] msec_range[17] 0.010000 - 0.020000 : 13 [20090313-13:17:09.309603510] msec_range[18] 0.000000 - 0.010000 : 775 [20090313-13:17:09.312125950] [20090313-13:17:09.314593602] [20090313-13:17:09.317133551] [20090313-13:17:09.319660003] [20090313-13:17:09.322654653] 1.1% User Time [20090313-13:17:09.325400897] 19.8% System Time [20090313-13:17:09.327846219] 20.9% CPU Utilization [20090313-13:17:09.339573797] Profilers reporting [20090313-13:17:18.926672808] Profilers postprocessing [20090313-13:17:19.186660231] Processing File : iostat.001 [20090313-13:17:19.189358940] Discovered iostat_interval=[5] [20090313-13:17:19.914638647] Processing Directory : sar.breakout.001 [20090313-13:17:19.916998354] Discovered sar_interval=[5] [20090313-13:17:20.099921633] Processing File : mpstat.001 [20090313-13:17:20.102544250] Discovered mpstat_interval=[5] [20090313-13:17:21.238179271] Stopping profiling. [20090313-13:17:21.243550011] Killing daemon. [20090313-13:17:22.471570934] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0001.09-03-13_13.05.28/analysis/oprofile.001 [20090313-13:17:22.474088100] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0001.09-03-13_13.05.28/analysis/oprofile-brief.001 [20090313-13:17:23.845963685] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-03-13_1304/btrfs-baseline' [20090313-13:17:25.644129054] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090313-13:17:28.180895167] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090313-13:17:28.369427888] PROCESSING COMMAND : 'run sequential_reads__threads_0008 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb num_threads=8' [20090313-13:17:28.414814125] new log requested [20090313-13:17:28.453227432] Running command ffsb [20090313-13:17:36.759304888] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb [20090313-13:17:36.772882371] Importing argument : num_threads=8 [20090313-13:17:36.800257924] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090313-13:17:36.869857266] FFSB version 6.0-RC2.1 started [20090313-13:17:36.872317015] [20090313-13:17:36.903931697] benchmark time = 300 [20090313-13:17:36.906183535] ThreadGroup 0 [20090313-13:17:36.908256797] ================ [20090313-13:17:36.910430964] num_threads = 8 [20090313-13:17:36.912421959] [20090313-13:17:36.914349213] read_random = off [20090313-13:17:36.916255883] read_size = 0 (0B) [20090313-13:17:36.918204895] read_blocksize = 4096 (4KB) [20090313-13:17:36.920075149] read_skip = off [20090313-13:17:36.922076896] read_skipsize = 0 (0B) [20090313-13:17:36.923921663] [20090313-13:17:36.925836078] write_random = off [20090313-13:17:36.927690866] write_size = 0 (0B) [20090313-13:17:36.929616583] fsync_file = 0 [20090313-13:17:36.931571730] write_blocksize = 0 (0B) [20090313-13:17:36.933474189] wait time = 0 [20090313-13:17:36.935316474] [20090313-13:17:36.937402907] op weights [20090313-13:17:36.939561020] read = 0 (0.00%) [20090313-13:17:36.941488211] readall = 1 (100.00%) [20090313-13:17:36.943480857] write = 0 (0.00%) [20090313-13:17:36.945312180] create = 0 (0.00%) [20090313-13:17:36.947306364] append = 0 (0.00%) [20090313-13:17:36.949191318] delete = 0 (0.00%) [20090313-13:17:36.951115296] metaop = 0 (0.00%) [20090313-13:17:36.952907943] createdir = 0 (0.00%) [20090313-13:17:36.954879517] stat = 0 (0.00%) [20090313-13:17:36.956758072] writeall = 0 (0.00%) [20090313-13:17:36.958666151] writeall_fsync = 0 (0.00%) [20090313-13:17:36.960496998] open_close = 0 (0.00%) [20090313-13:17:36.962411575] write_fsync = 0 (0.00%) [20090313-13:17:36.964267047] create_fsync = 0 (0.00%) [20090313-13:17:36.966172353] append_fsync = 0 (0.00%) [20090313-13:17:36.967960094] [20090313-13:17:36.969894847] FileSystem /mnt/ffsb1 [20090313-13:17:36.971752881] ========== [20090313-13:17:36.973653032] num_dirs = 0 [20090313-13:17:36.975485776] starting files = 1024 [20090313-13:17:36.977407035] [20090313-13:17:36.979247630] min file size = 36700160 (35MB) [20090313-13:17:36.981149879] max file size = 36700160 (35MB) [20090313-13:17:36.982917636] directio = off [20090313-13:17:36.984843946] alignedio = on [20090313-13:17:36.986676199] bufferedio = off [20090313-13:17:36.988555209] [20090313-13:17:36.990391280] aging is off [20090313-13:17:36.992350169] current utilization = 51.26% [20090313-13:17:36.994170021] [20090313-13:17:36.996103354] checking existing fs: /mnt/ffsb1 [20090313-13:17:37.706453441] fs setup took 0 secs [20090313-13:17:38.756971925] Syncing()...1 sec [20090313-13:17:38.759089924] Starting Actual Benchmark At: Fri Mar 13 13:17:38 2009 [20090313-13:17:38.773031025] [20090313-13:22:43.301389088] Syncing()...0 sec [20090313-13:22:43.359974414] FFSB benchmark finished at: Fri Mar 13 13:22:42 2009 [20090313-13:22:43.363305469] [20090313-13:22:43.366459765] Results: [20090313-13:22:43.394044387] Benchmark took 304.23 sec [20090313-13:22:43.396576695] [20090313-13:22:43.399459675] Total Results [20090313-13:22:43.416133213] =============== [20090313-13:22:43.419309537] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090313-13:22:43.422303444] ======= ============ ========= ======= =========== ========== [20090313-13:22:43.425432277] readall : 6944000 22824.74 100.000% 100.000% 89.2MB/sec [20090313-13:22:43.428409230] - [20090313-13:22:43.430950443] 22824.74 Transactions per Second [20090313-13:22:43.433562763] [20090313-13:22:43.436254605] Throughput Results [20090313-13:22:43.452389617] =================== [20090313-13:22:43.454903528] Read Throughput: 89.2MB/sec [20090313-13:22:43.457545053] [20090313-13:22:43.460141905] System Call Latency statistics in millisecs [20090313-13:22:43.462597672] ===== [20090313-13:22:43.465277698] Min Avg Max Total Calls [20090313-13:22:43.467821623] ======== ======== ======== ============ [20090313-13:22:43.470444972] [ open] 0.007000 6.175810 504.449005 775 [20090313-13:22:43.473015637] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090313-13:22:43.475632340] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090313-13:22:43.478253609] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090313-13:22:43.480795606] msec_range[3] 500.000000 - 1000.000000 : 2 [20090313-13:22:43.483285596] msec_range[4] 200.000000 - 500.000000 : 10 [20090313-13:22:43.485866438] msec_range[5] 100.000000 - 200.000000 : 3 [20090313-13:22:43.488388847] msec_range[6] 50.000000 - 100.000000 : 1 [20090313-13:22:43.546130755] msec_range[7] 20.000000 - 50.000000 : 1 [20090313-13:22:43.549080081] msec_range[8] 10.000000 - 20.000000 : 4 [20090313-13:22:43.551848112] msec_range[9] 5.000000 - 10.000000 : 0 [20090313-13:22:43.555107543] msec_range[10] 2.000000 - 5.000000 : 0 [20090313-13:22:43.558322116] msec_range[11] 1.000000 - 2.000000 : 1 [20090313-13:22:43.560889495] msec_range[12] 0.500000 - 1.000000 : 0 [20090313-13:22:43.563400070] msec_range[13] 0.200000 - 0.500000 : 1 [20090313-13:22:43.566073525] msec_range[14] 0.100000 - 0.200000 : 0 [20090313-13:22:43.568450918] msec_range[15] 0.050000 - 0.100000 : 270 [20090313-13:22:43.571003715] msec_range[16] 0.020000 - 0.050000 : 464 [20090313-13:22:43.573515447] msec_range[17] 0.010000 - 0.020000 : 13 [20090313-13:22:43.576170571] msec_range[18] 0.000000 - 0.010000 : 5 [20090313-13:22:43.578716289] [20090313-13:22:43.581377547] [ read] 0.001000 0.347862 3123.270020 6944000 [20090313-13:22:43.584296628] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090313-13:22:43.588474470] msec_range[1] 2000.000000 - 5000.000000 : 19 [20090313-13:22:43.591204958] msec_range[2] 1000.000000 - 2000.000000 : 240 [20090313-13:22:43.594221292] msec_range[3] 500.000000 - 1000.000000 : 953 [20090313-13:22:43.597153175] msec_range[4] 200.000000 - 500.000000 : 2457 [20090313-13:22:43.600000272] msec_range[5] 100.000000 - 200.000000 : 2200 [20090313-13:22:43.602905108] msec_range[6] 50.000000 - 100.000000 : 1581 [20090313-13:22:43.605747967] msec_range[7] 20.000000 - 50.000000 : 1291 [20090313-13:22:43.609277527] msec_range[8] 10.000000 - 20.000000 : 684 [20090313-13:22:43.612028713] msec_range[9] 5.000000 - 10.000000 : 2132 [20090313-13:22:43.614970524] msec_range[10] 2.000000 - 5.000000 : 12286 [20090313-13:22:43.617595862] msec_range[11] 1.000000 - 2.000000 : 827 [20090313-13:22:43.620199308] msec_range[12] 0.500000 - 1.000000 : 227 [20090313-13:22:43.622697692] msec_range[13] 0.200000 - 0.500000 : 465 [20090313-13:22:43.625305268] msec_range[14] 0.100000 - 0.200000 : 859 [20090313-13:22:43.627787345] msec_range[15] 0.050000 - 0.100000 : 1294 [20090313-13:22:43.630308105] msec_range[16] 0.020000 - 0.050000 : 20614 [20090313-13:22:43.632767603] msec_range[17] 0.010000 - 0.020000 : 219238 [20090313-13:22:43.635342584] msec_range[18] 0.000000 - 0.010000 : 6676633 [20090313-13:22:43.638172645] [20090313-13:22:43.641095446] [ close] 0.003000 0.007979 0.020000 775 [20090313-13:22:43.643903494] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090313-13:22:43.646740151] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090313-13:22:43.649610099] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090313-13:22:43.652581450] msec_range[3] 500.000000 - 1000.000000 : 0 [20090313-13:22:43.655292331] msec_range[4] 200.000000 - 500.000000 : 0 [20090313-13:22:43.657998477] msec_range[5] 100.000000 - 200.000000 : 0 [20090313-13:22:43.660491408] msec_range[6] 50.000000 - 100.000000 : 0 [20090313-13:22:43.663184575] msec_range[7] 20.000000 - 50.000000 : 0 [20090313-13:22:43.665828498] msec_range[8] 10.000000 - 20.000000 : 0 [20090313-13:22:43.668764113] msec_range[9] 5.000000 - 10.000000 : 0 [20090313-13:22:43.671641523] msec_range[10] 2.000000 - 5.000000 : 0 [20090313-13:22:43.674416698] msec_range[11] 1.000000 - 2.000000 : 0 [20090313-13:22:43.676956719] msec_range[12] 0.500000 - 1.000000 : 0 [20090313-13:22:43.679581599] msec_range[13] 0.200000 - 0.500000 : 0 [20090313-13:22:43.682421076] msec_range[14] 0.100000 - 0.200000 : 0 [20090313-13:22:43.685045894] msec_range[15] 0.050000 - 0.100000 : 0 [20090313-13:22:43.687867983] msec_range[16] 0.020000 - 0.050000 : 1 [20090313-13:22:43.690605157] msec_range[17] 0.010000 - 0.020000 : 153 [20090313-13:22:43.693195774] msec_range[18] 0.000000 - 0.010000 : 621 [20090313-13:22:43.696089559] [20090313-13:22:43.698775829] [20090313-13:22:43.701371993] [20090313-13:22:43.703935620] [20090313-13:22:43.706613775] 1.2% User Time [20090313-13:22:43.709212484] 20.4% System Time [20090313-13:22:43.711743073] 21.6% CPU Utilization [20090313-13:22:43.714208976] Profilers reporting [20090313-13:22:56.131627260] Profilers postprocessing [20090313-13:22:56.384066704] Processing File : iostat.001 [20090313-13:22:56.386462693] Discovered iostat_interval=[5] [20090313-13:22:57.100311633] Processing Directory : sar.breakout.001 [20090313-13:22:57.102611468] Discovered sar_interval=[5] [20090313-13:22:57.269869061] Processing File : mpstat.001 [20090313-13:22:57.272402094] Discovered mpstat_interval=[5] [20090313-13:22:58.408315741] Stopping profiling. [20090313-13:22:58.413151906] Killing daemon. [20090313-13:22:59.648618413] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0008.09-03-13_13.17.28/analysis/oprofile.001 [20090313-13:22:59.651134468] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0008.09-03-13_13.17.28/analysis/oprofile-brief.001 [20090313-13:23:00.758066297] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-03-13_1304/btrfs-baseline' [20090313-13:23:02.653867814] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090313-13:23:05.253494188] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090313-13:23:05.415238763] PROCESSING COMMAND : 'run sequential_reads__threads_0032 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb num_threads=32' [20090313-13:23:05.460799176] new log requested [20090313-13:23:05.499343987] Running command ffsb [20090313-13:23:13.888601224] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb [20090313-13:23:13.902490402] Importing argument : num_threads=32 [20090313-13:23:13.929460070] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090313-13:23:14.000437904] FFSB version 6.0-RC2.1 started [20090313-13:23:14.002796733] [20090313-13:23:14.137326082] benchmark time = 300 [20090313-13:23:14.139485773] ThreadGroup 0 [20090313-13:23:14.141645274] ================ [20090313-13:23:14.143782218] num_threads = 32 [20090313-13:23:14.145864284] [20090313-13:23:14.147749477] read_random = off [20090313-13:23:14.149692776] read_size = 0 (0B) [20090313-13:23:14.151556290] read_blocksize = 4096 (4KB) [20090313-13:23:14.153480327] read_skip = off [20090313-13:23:14.155287207] read_skipsize = 0 (0B) [20090313-13:23:14.157242714] [20090313-13:23:14.159056402] write_random = off [20090313-13:23:14.160986443] write_size = 0 (0B) [20090313-13:23:14.162846752] fsync_file = 0 [20090313-13:23:14.164749707] write_blocksize = 0 (0B) [20090313-13:23:14.166793845] wait time = 0 [20090313-13:23:14.169000136] [20090313-13:23:14.170968923] op weights [20090313-13:23:14.173001655] read = 0 (0.00%) [20090313-13:23:14.174929351] readall = 1 (100.00%) [20090313-13:23:14.176878288] write = 0 (0.00%) [20090313-13:23:14.178931353] create = 0 (0.00%) [20090313-13:23:14.180867084] append = 0 (0.00%) [20090313-13:23:14.182746466] delete = 0 (0.00%) [20090313-13:23:14.184687129] metaop = 0 (0.00%) [20090313-13:23:14.186538849] createdir = 0 (0.00%) [20090313-13:23:14.188480731] stat = 0 (0.00%) [20090313-13:23:14.190326394] writeall = 0 (0.00%) [20090313-13:23:14.192270787] writeall_fsync = 0 (0.00%) [20090313-13:23:14.194121695] open_close = 0 (0.00%) [20090313-13:23:14.196041416] write_fsync = 0 (0.00%) [20090313-13:23:14.197892722] create_fsync = 0 (0.00%) [20090313-13:23:14.199859189] append_fsync = 0 (0.00%) [20090313-13:23:14.201711521] [20090313-13:23:14.203629157] FileSystem /mnt/ffsb1 [20090313-13:23:14.205453541] ========== [20090313-13:23:14.207543441] num_dirs = 0 [20090313-13:23:14.209417538] starting files = 1024 [20090313-13:23:14.211387139] [20090313-13:23:14.213376426] min file size = 36700160 (35MB) [20090313-13:23:14.215264806] max file size = 36700160 (35MB) [20090313-13:23:14.217233204] directio = off [20090313-13:23:14.219056546] alignedio = on [20090313-13:23:14.220996533] bufferedio = off [20090313-13:23:14.222862273] [20090313-13:23:14.224770013] aging is off [20090313-13:23:14.226631961] current utilization = 51.26% [20090313-13:23:14.228528205] [20090313-13:23:14.230374081] checking existing fs: /mnt/ffsb1 [20090313-13:23:15.020784317] fs setup took 0 secs [20090313-13:23:16.161096046] Syncing()...1 sec [20090313-13:23:16.163370723] Starting Actual Benchmark At: Fri Mar 13 13:23:16 2009 [20090313-13:23:16.177397444] [20090313-13:28:25.743929100] Syncing()...0 sec [20090313-13:28:25.832659860] FFSB benchmark finished at: Fri Mar 13 13:28:25 2009 [20090313-13:28:25.836038325] [20090313-13:28:25.839277404] Results: [20090313-13:28:25.899267743] Benchmark took 309.30 sec [20090313-13:28:25.901728516] [20090313-13:28:25.904747441] Total Results [20090313-13:28:25.921141423] =============== [20090313-13:28:25.924006999] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090313-13:28:25.926863317] ======= ============ ========= ======= =========== ========== [20090313-13:28:25.929569819] readall : 6657280 21523.76 100.000% 100.000% 84.1MB/sec [20090313-13:28:25.932442095] - [20090313-13:28:25.935258260] 21523.76 Transactions per Second [20090313-13:28:25.937995743] [20090313-13:28:25.940469372] Throughput Results [20090313-13:28:25.957435898] =================== [20090313-13:28:25.960277691] Read Throughput: 84.1MB/sec [20090313-13:28:25.963404352] [20090313-13:28:25.966166942] System Call Latency statistics in millisecs [20090313-13:28:25.968957418] ===== [20090313-13:28:25.971689490] Min Avg Max Total Calls [20090313-13:28:25.974555355] ======== ======== ======== ============ [20090313-13:28:25.977237020] [ open] 0.006000 13.951787 772.284973 743 [20090313-13:28:25.979754065] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090313-13:28:25.982538598] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090313-13:28:25.985157355] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090313-13:28:25.987706978] msec_range[3] 500.000000 - 1000.000000 : 8 [20090313-13:28:25.990358500] msec_range[4] 200.000000 - 500.000000 : 11 [20090313-13:28:25.992990279] msec_range[5] 100.000000 - 200.000000 : 3 [20090313-13:28:25.995458624] msec_range[6] 50.000000 - 100.000000 : 3 [20090313-13:28:25.997959683] msec_range[7] 20.000000 - 50.000000 : 1 [20090313-13:28:26.000480652] msec_range[8] 10.000000 - 20.000000 : 0 [20090313-13:28:26.003459720] msec_range[9] 5.000000 - 10.000000 : 0 [20090313-13:28:26.006203737] msec_range[10] 2.000000 - 5.000000 : 0 [20090313-13:28:26.008880155] msec_range[11] 1.000000 - 2.000000 : 0 [20090313-13:28:26.011486343] msec_range[12] 0.500000 - 1.000000 : 0 [20090313-13:28:26.014237405] msec_range[13] 0.200000 - 0.500000 : 0 [20090313-13:28:26.017088991] msec_range[14] 0.100000 - 0.200000 : 2 [20090313-13:28:26.019574298] msec_range[15] 0.050000 - 0.100000 : 287 [20090313-13:28:26.022341531] msec_range[16] 0.020000 - 0.050000 : 390 [20090313-13:28:26.024805940] msec_range[17] 0.010000 - 0.020000 : 11 [20090313-13:28:26.027445144] msec_range[18] 0.000000 - 0.010000 : 27 [20090313-13:28:26.029953753] [20090313-13:28:26.032508546] [ read] 0.001000 1.467335 4290.107910 6657280 [20090313-13:28:26.035009510] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090313-13:28:26.067028007] msec_range[1] 2000.000000 - 5000.000000 : 357 [20090313-13:28:26.069751733] msec_range[2] 1000.000000 - 2000.000000 : 2490 [20090313-13:28:26.072779500] msec_range[3] 500.000000 - 1000.000000 : 5837 [20090313-13:28:26.075904358] msec_range[4] 200.000000 - 500.000000 : 3498 [20090313-13:28:26.078561616] msec_range[5] 100.000000 - 200.000000 : 425 [20090313-13:28:26.081507567] msec_range[6] 50.000000 - 100.000000 : 256 [20090313-13:28:26.085018473] msec_range[7] 20.000000 - 50.000000 : 216 [20090313-13:28:26.087835372] msec_range[8] 10.000000 - 20.000000 : 104 [20090313-13:28:26.090745563] msec_range[9] 5.000000 - 10.000000 : 2493 [20090313-13:28:26.093443952] msec_range[10] 2.000000 - 5.000000 : 17477 [20090313-13:28:26.096185631] msec_range[11] 1.000000 - 2.000000 : 429 [20090313-13:28:26.098849540] msec_range[12] 0.500000 - 1.000000 : 169 [20090313-13:28:26.101449508] msec_range[13] 0.200000 - 0.500000 : 356 [20090313-13:28:26.103990510] msec_range[14] 0.100000 - 0.200000 : 574 [20090313-13:28:26.107026183] msec_range[15] 0.050000 - 0.100000 : 994 [20090313-13:28:26.109655688] msec_range[16] 0.020000 - 0.050000 : 22551 [20090313-13:28:26.112195078] msec_range[17] 0.010000 - 0.020000 : 363947 [20090313-13:28:26.114935777] msec_range[18] 0.000000 - 0.010000 : 6235107 [20090313-13:28:26.117697290] [20090313-13:28:26.120265419] [ close] 0.003000 0.008007 0.016000 743 [20090313-13:28:26.122846046] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090313-13:28:26.125581586] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090313-13:28:26.128238579] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090313-13:28:26.130967869] msec_range[3] 500.000000 - 1000.000000 : 0 [20090313-13:28:26.134035422] msec_range[4] 200.000000 - 500.000000 : 0 [20090313-13:28:26.136830714] msec_range[5] 100.000000 - 200.000000 : 0 [20090313-13:28:26.140424358] msec_range[6] 50.000000 - 100.000000 : 0 [20090313-13:28:26.143113056] msec_range[7] 20.000000 - 50.000000 : 0 [20090313-13:28:26.145942257] msec_range[8] 10.000000 - 20.000000 : 0 [20090313-13:28:26.149307244] msec_range[9] 5.000000 - 10.000000 : 0 [20090313-13:28:26.152394606] msec_range[10] 2.000000 - 5.000000 : 0 [20090313-13:28:26.155217746] msec_range[11] 1.000000 - 2.000000 : 0 [20090313-13:28:26.157994580] msec_range[12] 0.500000 - 1.000000 : 0 [20090313-13:28:26.160535369] msec_range[13] 0.200000 - 0.500000 : 0 [20090313-13:28:26.163153446] msec_range[14] 0.100000 - 0.200000 : 0 [20090313-13:28:26.165643561] msec_range[15] 0.050000 - 0.100000 : 0 [20090313-13:28:26.168263954] msec_range[16] 0.020000 - 0.050000 : 0 [20090313-13:28:26.170774612] msec_range[17] 0.010000 - 0.020000 : 162 [20090313-13:28:26.173342474] msec_range[18] 0.000000 - 0.010000 : 581 [20090313-13:28:26.175850005] [20090313-13:28:26.178511147] [20090313-13:28:26.181036648] [20090313-13:28:26.183611878] [20090313-13:28:26.186081454] 1.1% User Time [20090313-13:28:26.188760135] 20.5% System Time [20090313-13:28:26.191393790] 21.6% CPU Utilization [20090313-13:28:26.193867901] Profilers reporting [20090313-13:28:38.007327769] Profilers postprocessing [20090313-13:28:38.279202284] Processing File : iostat.001 [20090313-13:28:38.281638444] Discovered iostat_interval=[5] [20090313-13:28:39.027903652] Processing Directory : sar.breakout.001 [20090313-13:28:39.030303544] Discovered sar_interval=[5] [20090313-13:28:39.207255951] Processing File : mpstat.001 [20090313-13:28:39.209627596] Discovered mpstat_interval=[5] [20090313-13:28:40.344279974] Stopping profiling. [20090313-13:28:40.348343559] Killing daemon. [20090313-13:28:41.577088717] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0032.09-03-13_13.23.05/analysis/oprofile.001 [20090313-13:28:41.579516803] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0032.09-03-13_13.23.05/analysis/oprofile-brief.001 [20090313-13:28:42.692062986] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-03-13_1304/btrfs-baseline'