[20090617-09:40:31.432028437] PROCESSING COMMAND : 'clearprofilers' [20090617-09:40:31.721593135] PROCESSING COMMAND : 'useprofiler iostat 5' [20090617-09:40:31.835670997] Checking for sar... [20090617-09:40:31.838031022] found [20090617-09:40:31.986462625] PROCESSING COMMAND : 'useprofiler sar 5' [20090617-09:40:32.103712934] Checking for sar... [20090617-09:40:32.106010895] found [20090617-09:40:32.258798956] PROCESSING COMMAND : 'useprofiler mpstat 5' [20090617-09:40:32.373210357] Checking for sar... [20090617-09:40:32.375634662] found [20090617-09:40:32.558887446] PROCESSING COMMAND : 'useprofiler oprofile' [20090617-09:40:32.718535672] Checking for gettext... [20090617-09:40:32.723597699] found [20090617-09:40:32.725898139] Checking for libiberty in autobench... [20090617-09:40:32.757455215] found [20090617-09:40:32.759802406] Checking for popt... [20090617-09:40:32.761881478] found [20090617-09:40:32.768298135] Checking for popt64... [20090617-09:40:32.770225458] found [20090617-09:40:32.772235585] Checking for oprofile... [20090617-09:40:32.795045440] found [20090617-09:40:32.858547516] opcontrol: oprofile 0.9.4 compiled on Nov 19 2008 09:09:21 [20090617-09:40:33.096066234] Daemon not running [20090617-09:40:35.480932682] OPROFILE : using callgraph [5] [20090617-09:40:35.721016184] Daemon not running [20090617-09:40:35.723246080] Separate options: none [20090617-09:40:35.725622481] vmlinux file: /boot/vmlinux-2.6.30-rc7-autokern1 [20090617-09:40:35.727616035] Image filter: none [20090617-09:40:35.729767094] Call-graph depth: 5 [20090617-09:40:35.949532641] PROCESSING COMMAND : 'umount /mnt/ffsb1 > /dev/null 2>&1' [20090617-09:40:36.026560017] PROCESSING COMMAND : 'set-sched noop' [20090617-09:40:36.349098933] PROCESSING COMMAND : 'mkresultdirs hks.austin.ibm.com benchmarks/results/btrfs/ffsb btrfs2 2009-06-17_0940 btrfs-newformat-6-17' [20090617-09:40:36.574489948] Connecting to hks.austin.ibm.com... [20090617-09:40:36.576750681] Remote working directory: /opt [20090617-09:40:36.579158668] Remote working directory: /opt/benchmarks/results/btrfs/ffsb [20090617-09:40:36.581350978] Couldn't create directory: Failure [20090617-09:40:36.583413949] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs2 [20090617-09:40:36.585674250] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs2 [20090617-09:40:36.587896016] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs2/2009-06-17_0940 [20090617-09:40:36.590044702] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs2/2009-06-17_0940 [20090617-09:40:36.592193711] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs2/2009-06-17_0940/btrfs-newformat-6-17 [20090617-09:40:36.663184706] PROCESSING COMMAND : 'mkfs.btrfs -V 2>&1' [20090617-09:40:36.697042714] mkfs.btrfs: invalid option -- V [20090617-09:40:36.700729768] usage: mkfs.btrfs [options] dev [ dev ... ] [20090617-09:40:36.703039905] options: [20090617-09:40:36.705213000] -A --alloc-start the offset to start the FS [20090617-09:40:36.707202753] -b --byte-count total number of bytes in the FS [20090617-09:40:36.709200693] -d --data data profile, raid0, raid1, raid10 or single [20090617-09:40:36.711565531] -l --leafsize size of btree leaves [20090617-09:40:36.713634013] -L --label set a label [20090617-09:40:36.715649995] -m --metadata metadata profile, values like data profile [20090617-09:40:36.717542154] -n --nodesize size of btree nodes [20090617-09:40:36.719572340] -s --sectorsize min block allocation [20090617-09:40:36.721544996] Btrfs v0.18-13-gb8420fa [20090617-09:40:36.796447903] PROCESSING COMMAND : 'mkfs.btrfs /dev/ffsbdev1' [20090617-09:40:36.833127179] [20090617-09:40:36.835290343] WARNING! - Btrfs v0.18-13-gb8420fa IS EXPERIMENTAL [20090617-09:40:36.837461726] WARNING! - see http://btrfs.wiki.kernel.org before using [20090617-09:40:36.839819706] [20090617-09:40:36.841855733] fs created label (null) on /dev/ffsbdev1 [20090617-09:40:36.843912084] nodesize 4096 leafsize 4096 sectorsize 4096 size 68.37GB [20090617-09:40:36.845810681] Btrfs v0.18-13-gb8420fa [20090617-09:40:37.087990957] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090617-09:40:37.379930715] PROCESSING COMMAND : 'run sequential_reads__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb num_threads=1' [20090617-09:40:37.427511459] new log requested [20090617-09:40:37.464712119] Running command ffsb [20090617-09:40:46.127329558] 06/17/2009-09:40:46 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb Succeeded [20090617-09:40:46.137989704] Importing argument : num_threads=1 [20090617-09:40:46.166506757] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090617-09:40:46.260706497] FFSB version 6.0-RC2.1 started [20090617-09:40:46.262879320] [20090617-09:40:46.265021413] benchmark time = 300 [20090617-09:40:46.267164552] ThreadGroup 0 [20090617-09:40:46.269441893] ================ [20090617-09:40:46.271368304] num_threads = 1 [20090617-09:40:46.273483118] [20090617-09:40:46.275687513] read_random = off [20090617-09:40:46.277823503] read_size = 0 (0B) [20090617-09:40:46.279813624] read_blocksize = 4096 (4KB) [20090617-09:40:46.281714542] read_skip = off [20090617-09:40:46.283713588] read_skipsize = 0 (0B) [20090617-09:40:46.285633365] [20090617-09:40:46.287625247] write_random = off [20090617-09:40:46.289505773] write_size = 0 (0B) [20090617-09:40:46.291528979] fsync_file = 0 [20090617-09:40:46.293497369] write_blocksize = 0 (0B) [20090617-09:40:46.295383758] wait time = 0 [20090617-09:40:46.297374189] [20090617-09:40:46.299215226] op weights [20090617-09:40:46.301196143] read = 0 (0.00%) [20090617-09:40:46.303083616] readall = 1 (100.00%) [20090617-09:40:46.305106030] write = 0 (0.00%) [20090617-09:40:46.307040919] create = 0 (0.00%) [20090617-09:40:46.308983869] append = 0 (0.00%) [20090617-09:40:46.310964057] delete = 0 (0.00%) [20090617-09:40:46.312862626] metaop = 0 (0.00%) [20090617-09:40:46.314833852] createdir = 0 (0.00%) [20090617-09:40:46.316801016] stat = 0 (0.00%) [20090617-09:40:46.318798457] writeall = 0 (0.00%) [20090617-09:40:46.320785486] writeall_fsync = 0 (0.00%) [20090617-09:40:46.322664558] open_close = 0 (0.00%) [20090617-09:40:46.324639085] write_fsync = 0 (0.00%) [20090617-09:40:46.326526689] create_fsync = 0 (0.00%) [20090617-09:40:46.328456979] append_fsync = 0 (0.00%) [20090617-09:40:46.330321311] [20090617-09:40:46.332308011] FileSystem /mnt/ffsb1 [20090617-09:40:46.334273708] ========== [20090617-09:40:46.336146485] num_dirs = 0 [20090617-09:40:46.338117025] starting files = 1024 [20090617-09:40:46.340020800] [20090617-09:40:46.341947601] min file size = 36700160 (35MB) [20090617-09:40:46.343959991] max file size = 36700160 (35MB) [20090617-09:40:46.345976403] directio = off [20090617-09:40:46.347897174] alignedio = on [20090617-09:40:46.349802630] bufferedio = off [20090617-09:40:46.351778035] [20090617-09:40:46.353666970] aging is off [20090617-09:40:46.355610574] current utilization = 0.00% [20090617-09:40:46.357643506] [20090617-09:40:46.359633840] checking existing fs: /mnt/ffsb1 [20090617-09:40:46.361607921] opendir: No such file or directory [20090617-09:40:46.363478003] recreating new fileset [20090617-09:47:07.693676146] fs setup took 381 secs [20090617-09:47:15.363001915] Syncing()...7 sec [20090617-09:47:15.365651709] Starting Actual Benchmark At: Wed Jun 17 09:47:15 2009 [20090617-09:47:15.469512113] [20090617-09:52:17.086628588] Syncing()...0 sec [20090617-09:52:17.149251111] FFSB benchmark finished at: Wed Jun 17 09:52:16 2009 [20090617-09:52:17.152636046] [20090617-09:52:17.155902495] Results: [20090617-09:52:17.186152229] Benchmark took 301.42 sec [20090617-09:52:17.235834054] [20090617-09:52:17.238445631] Total Results [20090617-09:52:17.255358321] =============== [20090617-09:52:17.258505709] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090617-09:52:17.261778986] ======= ============ ========= ======= =========== ========== [20090617-09:52:17.264746557] readall : 7329280 24316.03 100.000% 100.000% 95MB/sec [20090617-09:52:17.267752226] - [20090617-09:52:17.270444853] 24316.03 Transactions per Second [20090617-09:52:17.273174266] [20090617-09:52:17.276090172] Throughput Results [20090617-09:52:17.292369846] =================== [20090617-09:52:17.295092639] Read Throughput: 95MB/sec [20090617-09:52:17.298186126] [20090617-09:52:17.300843612] System Call Latency statistics in millisecs [20090617-09:52:17.303657684] ===== [20090617-09:52:17.306327988] Min Avg Max Total Calls [20090617-09:52:17.309011150] ======== ======== ======== ============ [20090617-09:52:17.311533756] [ open] 0.012000 0.245527 15.974000 818 [20090617-09:52:17.314367500] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-09:52:17.317450501] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-09:52:17.320123218] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-09:52:17.322657879] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-09:52:17.325280024] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-09:52:17.327866364] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-09:52:17.330479932] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-09:52:17.333036525] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-09:52:17.335784351] msec_range[8] 10.000000 - 20.000000 : 7 [20090617-09:52:17.338355954] msec_range[9] 5.000000 - 10.000000 : 8 [20090617-09:52:17.341244257] msec_range[10] 2.000000 - 5.000000 : 6 [20090617-09:52:17.343824970] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-09:52:17.346546247] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-09:52:17.349091418] msec_range[13] 0.200000 - 0.500000 : 0 [20090617-09:52:17.351664349] msec_range[14] 0.100000 - 0.200000 : 1 [20090617-09:52:17.354283999] msec_range[15] 0.050000 - 0.100000 : 307 [20090617-09:52:17.356979781] msec_range[16] 0.020000 - 0.050000 : 477 [20090617-09:52:17.359440347] msec_range[17] 0.010000 - 0.020000 : 12 [20090617-09:52:17.362022770] msec_range[18] 0.000000 - 0.010000 : 0 [20090617-09:52:17.364603950] [20090617-09:52:17.367362865] [ read] 0.001000 0.040800 264.691010 7329280 [20090617-09:52:17.371251578] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-09:52:17.374177050] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-09:52:17.377391702] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-09:52:17.380473855] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-09:52:17.383308817] msec_range[4] 200.000000 - 500.000000 : 1 [20090617-09:52:17.385895585] msec_range[5] 100.000000 - 200.000000 : 4 [20090617-09:52:17.388599541] msec_range[6] 50.000000 - 100.000000 : 412 [20090617-09:52:17.391169237] msec_range[7] 20.000000 - 50.000000 : 460 [20090617-09:52:17.393870057] msec_range[8] 10.000000 - 20.000000 : 643 [20090617-09:52:17.396371095] msec_range[9] 5.000000 - 10.000000 : 6858 [20090617-09:52:17.399429527] msec_range[10] 2.000000 - 5.000000 : 38482 [20090617-09:52:17.402731307] msec_range[11] 1.000000 - 2.000000 : 994 [20090617-09:52:17.405467715] msec_range[12] 0.500000 - 1.000000 : 145 [20090617-09:52:17.408236619] msec_range[13] 0.200000 - 0.500000 : 632 [20090617-09:52:17.410901270] msec_range[14] 0.100000 - 0.200000 : 475 [20090617-09:52:17.413811419] msec_range[15] 0.050000 - 0.100000 : 1081 [20090617-09:52:17.416425372] msec_range[16] 0.020000 - 0.050000 : 450 [20090617-09:52:17.419375243] msec_range[17] 0.010000 - 0.020000 : 58387 [20090617-09:52:17.422020485] msec_range[18] 0.000000 - 0.010000 : 7220256 [20090617-09:52:17.424930591] [20090617-09:52:17.427515781] [ close] 0.003000 0.007422 0.017000 818 [20090617-09:52:17.430330609] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-09:52:17.433033858] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-09:52:17.435843903] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-09:52:17.438942125] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-09:52:17.441686439] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-09:52:17.444468662] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-09:52:17.447072932] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-09:52:17.449692763] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-09:52:17.452176422] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-09:52:17.454896956] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-09:52:17.457320482] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-09:52:17.459951172] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-09:52:17.462430540] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-09:52:17.465207331] msec_range[13] 0.200000 - 0.500000 : 0 [20090617-09:52:17.467998324] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-09:52:17.470522126] msec_range[15] 0.050000 - 0.100000 : 0 [20090617-09:52:17.473451577] msec_range[16] 0.020000 - 0.050000 : 0 [20090617-09:52:17.476173014] msec_range[17] 0.010000 - 0.020000 : 81 [20090617-09:52:17.478775634] msec_range[18] 0.000000 - 0.010000 : 737 [20090617-09:52:17.481267015] [20090617-09:52:17.483860307] [20090617-09:52:17.486355997] [20090617-09:52:17.488978001] [20090617-09:52:17.491462533] 1.0% User Time [20090617-09:52:17.494653809] 19.2% System Time [20090617-09:52:17.497542472] 20.2% CPU Utilization [20090617-09:52:17.539271370] Profilers reporting [20090617-09:52:26.320211540] Profilers postprocessing [20090617-09:52:26.560115070] Processing File : iostat.001 [20090617-09:52:26.562342322] Discovered iostat_interval=[5] [20090617-09:52:27.316908735] Processing Directory : sar.breakout.001 [20090617-09:52:27.318805678] Discovered sar_interval=[5] [20090617-09:52:27.491153862] Processing File : mpstat.001 [20090617-09:52:27.494443167] Discovered mpstat_interval=[5] [20090617-09:52:28.637714099] Stopping profiling. [20090617-09:52:28.644588984] Killing daemon. [20090617-09:52:29.884062901] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0001.09-06-17_09.40.37/analysis/oprofile.001 [20090617-09:52:29.886431490] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0001.09-06-17_09.40.37/analysis/oprofile-brief.001 [20090617-09:52:31.049451655] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-06-17_0940/btrfs-newformat-6-17' [20090617-09:52:34.330933747] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090617-09:52:36.650429240] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090617-09:52:36.908874192] PROCESSING COMMAND : 'run sequential_reads__threads_0008 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb num_threads=8' [20090617-09:52:36.954430238] new log requested [20090617-09:52:36.989800363] Running command ffsb [20090617-09:52:45.925572476] 06/17/2009-09:52:45 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb Succeeded [20090617-09:52:45.936305056] Importing argument : num_threads=8 [20090617-09:52:45.965183304] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090617-09:52:46.040928209] FFSB version 6.0-RC2.1 started [20090617-09:52:46.043279302] [20090617-09:52:46.074011362] benchmark time = 300 [20090617-09:52:46.075969006] ThreadGroup 0 [20090617-09:52:46.077768477] ================ [20090617-09:52:46.080005925] num_threads = 8 [20090617-09:52:46.081996145] [20090617-09:52:46.083929954] read_random = off [20090617-09:52:46.085810391] read_size = 0 (0B) [20090617-09:52:46.087883628] read_blocksize = 4096 (4KB) [20090617-09:52:46.090215790] read_skip = off [20090617-09:52:46.092420380] read_skipsize = 0 (0B) [20090617-09:52:46.094686580] [20090617-09:52:46.096723738] write_random = off [20090617-09:52:46.098666657] write_size = 0 (0B) [20090617-09:52:46.100532331] fsync_file = 0 [20090617-09:52:46.102499502] write_blocksize = 0 (0B) [20090617-09:52:46.104393508] wait time = 0 [20090617-09:52:46.106328824] [20090617-09:52:46.108181176] op weights [20090617-09:52:46.110151350] read = 0 (0.00%) [20090617-09:52:46.112061980] readall = 1 (100.00%) [20090617-09:52:46.113989391] write = 0 (0.00%) [20090617-09:52:46.115840787] create = 0 (0.00%) [20090617-09:52:46.117780760] append = 0 (0.00%) [20090617-09:52:46.119738803] delete = 0 (0.00%) [20090617-09:52:46.121661576] metaop = 0 (0.00%) [20090617-09:52:46.123512397] createdir = 0 (0.00%) [20090617-09:52:46.125462647] stat = 0 (0.00%) [20090617-09:52:46.127344285] writeall = 0 (0.00%) [20090617-09:52:46.129260388] writeall_fsync = 0 (0.00%) [20090617-09:52:46.131098215] open_close = 0 (0.00%) [20090617-09:52:46.133016359] write_fsync = 0 (0.00%) [20090617-09:52:46.134866046] create_fsync = 0 (0.00%) [20090617-09:52:46.136785791] append_fsync = 0 (0.00%) [20090617-09:52:46.138617344] [20090617-09:52:46.140542007] FileSystem /mnt/ffsb1 [20090617-09:52:46.142413281] ========== [20090617-09:52:46.144351178] num_dirs = 0 [20090617-09:52:46.146205521] starting files = 1024 [20090617-09:52:46.148162303] [20090617-09:52:46.150041272] min file size = 36700160 (35MB) [20090617-09:52:46.151958243] max file size = 36700160 (35MB) [20090617-09:52:46.153808564] directio = off [20090617-09:52:46.155724643] alignedio = on [20090617-09:52:46.157580688] bufferedio = off [20090617-09:52:46.159497923] [20090617-09:52:46.161332528] aging is off [20090617-09:52:46.163270892] current utilization = 51.26% [20090617-09:52:46.165121890] [20090617-09:52:46.167048842] checking existing fs: /mnt/ffsb1 [20090617-09:52:46.639926891] fs setup took 0 secs [20090617-09:52:47.583163519] Syncing()...0 sec [20090617-09:52:47.585094334] Starting Actual Benchmark At: Wed Jun 17 09:52:47 2009 [20090617-09:52:47.599792107] [20090617-09:57:51.121913093] Syncing()...0 sec [20090617-09:57:51.165379521] FFSB benchmark finished at: Wed Jun 17 09:57:50 2009 [20090617-09:57:51.168850806] [20090617-09:57:51.172140351] Results: [20090617-09:57:51.211386086] Benchmark took 303.15 sec [20090617-09:57:51.214629979] [20090617-09:57:51.217754221] Total Results [20090617-09:57:51.234734536] =============== [20090617-09:57:51.237293943] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090617-09:57:51.240039113] ======= ============ ========= ======= =========== ========== [20090617-09:57:51.242463820] readall : 7069440 23320.02 100.000% 100.000% 91.1MB/sec [20090617-09:57:51.245332508] - [20090617-09:57:51.248144788] 23320.02 Transactions per Second [20090617-09:57:51.250985793] [20090617-09:57:51.253740036] Throughput Results [20090617-09:57:51.270004689] =================== [20090617-09:57:51.272904831] Read Throughput: 91.1MB/sec [20090617-09:57:51.275865045] [20090617-09:57:51.279029380] System Call Latency statistics in millisecs [20090617-09:57:51.281667616] ===== [20090617-09:57:51.284296526] Min Avg Max Total Calls [20090617-09:57:51.287002785] ======== ======== ======== ============ [20090617-09:57:51.289705058] [ open] 0.006000 12.869919 1478.810059 789 [20090617-09:57:51.306108576] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-09:57:51.308730184] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-09:57:51.311197870] msec_range[2] 1000.000000 - 2000.000000 : 2 [20090617-09:57:51.313787448] msec_range[3] 500.000000 - 1000.000000 : 5 [20090617-09:57:51.316251531] msec_range[4] 200.000000 - 500.000000 : 10 [20090617-09:57:51.318978327] msec_range[5] 100.000000 - 200.000000 : 3 [20090617-09:57:51.322221636] msec_range[6] 50.000000 - 100.000000 : 2 [20090617-09:57:51.324929807] msec_range[7] 20.000000 - 50.000000 : 3 [20090617-09:57:51.327482644] msec_range[8] 10.000000 - 20.000000 : 1 [20090617-09:57:51.330300453] msec_range[9] 5.000000 - 10.000000 : 1 [20090617-09:57:51.332968145] msec_range[10] 2.000000 - 5.000000 : 2 [20090617-09:57:51.335457299] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-09:57:51.338031506] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-09:57:51.340709787] msec_range[13] 0.200000 - 0.500000 : 1 [20090617-09:57:51.343184333] msec_range[14] 0.100000 - 0.200000 : 7 [20090617-09:57:51.345730555] msec_range[15] 0.050000 - 0.100000 : 372 [20090617-09:57:51.348304767] msec_range[16] 0.020000 - 0.050000 : 371 [20090617-09:57:51.350903194] msec_range[17] 0.010000 - 0.020000 : 4 [20090617-09:57:51.353349494] msec_range[18] 0.000000 - 0.010000 : 5 [20090617-09:57:51.355911165] [20090617-09:57:51.358371830] [ read] 0.001000 0.339826 3061.019043 7069440 [20090617-09:57:51.360937493] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-09:57:51.363407606] msec_range[1] 2000.000000 - 5000.000000 : 72 [20090617-09:57:51.365947837] msec_range[2] 1000.000000 - 2000.000000 : 376 [20090617-09:57:51.368437428] msec_range[3] 500.000000 - 1000.000000 : 593 [20090617-09:57:51.371007307] msec_range[4] 200.000000 - 500.000000 : 2160 [20090617-09:57:51.373593422] msec_range[5] 100.000000 - 200.000000 : 1751 [20090617-09:57:51.376156280] msec_range[6] 50.000000 - 100.000000 : 1135 [20090617-09:57:51.378740590] msec_range[7] 20.000000 - 50.000000 : 916 [20090617-09:57:51.381199458] msec_range[8] 10.000000 - 20.000000 : 423 [20090617-09:57:51.383771728] msec_range[9] 5.000000 - 10.000000 : 4028 [20090617-09:57:51.386298946] msec_range[10] 2.000000 - 5.000000 : 34072 [20090617-09:57:51.388965155] msec_range[11] 1.000000 - 2.000000 : 1109 [20090617-09:57:51.391423456] msec_range[12] 0.500000 - 1.000000 : 86 [20090617-09:57:51.394280128] msec_range[13] 0.200000 - 0.500000 : 436 [20090617-09:57:51.396761397] msec_range[14] 0.100000 - 0.200000 : 882 [20090617-09:57:51.399538608] msec_range[15] 0.050000 - 0.100000 : 467 [20090617-09:57:51.402475234] msec_range[16] 0.020000 - 0.050000 : 3948 [20090617-09:57:51.405461605] msec_range[17] 0.010000 - 0.020000 : 261786 [20090617-09:57:51.408278855] msec_range[18] 0.000000 - 0.010000 : 6755200 [20090617-09:57:51.411362699] [20090617-09:57:51.414223060] [ close] 0.004000 0.008063 0.018000 789 [20090617-09:57:51.417014615] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-09:57:51.419578337] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-09:57:51.422454727] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-09:57:51.425284549] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-09:57:51.427938163] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-09:57:51.430820677] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-09:57:51.434294659] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-09:57:51.438308127] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-09:57:51.441369883] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-09:57:51.444402713] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-09:57:51.447447740] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-09:57:51.450105718] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-09:57:51.453041889] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-09:57:51.455814178] msec_range[13] 0.200000 - 0.500000 : 0 [20090617-09:57:51.458508676] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-09:57:51.461010556] msec_range[15] 0.050000 - 0.100000 : 0 [20090617-09:57:51.463753174] msec_range[16] 0.020000 - 0.050000 : 0 [20090617-09:57:51.466298004] msec_range[17] 0.010000 - 0.020000 : 163 [20090617-09:57:51.468864661] msec_range[18] 0.000000 - 0.010000 : 626 [20090617-09:57:51.471361021] [20090617-09:57:51.473985530] [20090617-09:57:51.476482743] [20090617-09:57:51.479079893] [20090617-09:57:51.481689366] 1.2% User Time [20090617-09:57:51.484286650] 19.6% System Time [20090617-09:57:51.486959459] 20.8% CPU Utilization [20090617-09:57:51.489561626] Profilers reporting [20090617-09:58:03.149677932] Profilers postprocessing [20090617-09:58:03.379921851] Processing File : iostat.001 [20090617-09:58:03.382237222] Discovered iostat_interval=[5] [20090617-09:58:04.130212497] Processing Directory : sar.breakout.001 [20090617-09:58:04.132583715] Discovered sar_interval=[5] [20090617-09:58:04.300756239] Processing File : mpstat.001 [20090617-09:58:04.303095740] Discovered mpstat_interval=[5] [20090617-09:58:05.443828772] Stopping profiling. [20090617-09:58:05.450933840] Killing daemon. [20090617-09:58:07.706293214] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0008.09-06-17_09.52.36/analysis/oprofile.001 [20090617-09:58:07.708649543] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0008.09-06-17_09.52.36/analysis/oprofile-brief.001 [20090617-09:58:08.871090541] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-06-17_0940/btrfs-newformat-6-17' [20090617-09:58:10.687912953] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090617-09:58:13.018253817] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090617-09:58:13.252850265] PROCESSING COMMAND : 'run sequential_reads__threads_0032 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb num_threads=32' [20090617-09:58:13.298388006] new log requested [20090617-09:58:13.328012875] Running command ffsb [20090617-09:58:22.221361771] 06/17/2009-09:58:22 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb Succeeded [20090617-09:58:22.232422324] Importing argument : num_threads=32 [20090617-09:58:22.261285910] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090617-09:58:22.336716679] FFSB version 6.0-RC2.1 started [20090617-09:58:22.339067942] [20090617-09:58:22.470013587] benchmark time = 300 [20090617-09:58:22.471955046] ThreadGroup 0 [20090617-09:58:22.473761332] ================ [20090617-09:58:22.475978106] num_threads = 32 [20090617-09:58:22.477899452] [20090617-09:58:22.479822986] read_random = off [20090617-09:58:22.481676631] read_size = 0 (0B) [20090617-09:58:22.483570610] read_blocksize = 4096 (4KB) [20090617-09:58:22.485654220] read_skip = off [20090617-09:58:22.488007990] read_skipsize = 0 (0B) [20090617-09:58:22.490240770] [20090617-09:58:22.492565343] write_random = off [20090617-09:58:22.494569844] write_size = 0 (0B) [20090617-09:58:22.496506264] fsync_file = 0 [20090617-09:58:22.498397269] write_blocksize = 0 (0B) [20090617-09:58:22.500337245] wait time = 0 [20090617-09:58:22.502282633] [20090617-09:58:22.504248952] op weights [20090617-09:58:22.506145578] read = 0 (0.00%) [20090617-09:58:22.508039457] readall = 1 (100.00%) [20090617-09:58:22.509974478] write = 0 (0.00%) [20090617-09:58:22.511898585] create = 0 (0.00%) [20090617-09:58:22.513758196] append = 0 (0.00%) [20090617-09:58:22.515893799] delete = 0 (0.00%) [20090617-09:58:22.517784469] metaop = 0 (0.00%) [20090617-09:58:22.519674621] createdir = 0 (0.00%) [20090617-09:58:22.521527446] stat = 0 (0.00%) [20090617-09:58:22.523440036] writeall = 0 (0.00%) [20090617-09:58:22.525284090] writeall_fsync = 0 (0.00%) [20090617-09:58:22.527188673] open_close = 0 (0.00%) [20090617-09:58:22.529142961] write_fsync = 0 (0.00%) [20090617-09:58:22.531125709] create_fsync = 0 (0.00%) [20090617-09:58:22.533100666] append_fsync = 0 (0.00%) [20090617-09:58:22.534969130] [20090617-09:58:22.536985818] FileSystem /mnt/ffsb1 [20090617-09:58:22.538851561] ========== [20090617-09:58:22.540768942] num_dirs = 0 [20090617-09:58:22.542634990] starting files = 1024 [20090617-09:58:22.544624068] [20090617-09:58:22.546492295] min file size = 36700160 (35MB) [20090617-09:58:22.548401433] max file size = 36700160 (35MB) [20090617-09:58:22.550256854] directio = off [20090617-09:58:22.552215523] alignedio = on [20090617-09:58:22.554079083] bufferedio = off [20090617-09:58:22.555980492] [20090617-09:58:22.557818970] aging is off [20090617-09:58:22.559743848] current utilization = 51.26% [20090617-09:58:22.561618722] [20090617-09:58:22.563521587] checking existing fs: /mnt/ffsb1 [20090617-09:58:22.941892909] fs setup took 0 secs [20090617-09:58:24.165713664] Syncing()...1 sec [20090617-09:58:24.168083588] Starting Actual Benchmark At: Wed Jun 17 09:58:24 2009 [20090617-09:58:24.182372576] [20090617-10:03:34.639013343] Syncing()...0 sec [20090617-10:03:34.694772712] FFSB benchmark finished at: Wed Jun 17 10:03:34 2009 [20090617-10:03:34.698221541] [20090617-10:03:34.701477481] Results: [20090617-10:03:34.747519855] Benchmark took 310.00 sec [20090617-10:03:34.750395582] [20090617-10:03:34.752960492] Total Results [20090617-10:03:34.769636343] =============== [20090617-10:03:34.772293935] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090617-10:03:34.775088925] ======= ============ ========= ======= =========== ========== [20090617-10:03:34.777949650] readall : 7266560 23440.76 100.000% 100.000% 91.6MB/sec [20090617-10:03:34.781073317] - [20090617-10:03:34.784134093] 23440.76 Transactions per Second [20090617-10:03:34.787356532] [20090617-10:03:34.790209285] Throughput Results [20090617-10:03:34.808892171] =================== [20090617-10:03:34.811817802] Read Throughput: 91.6MB/sec [20090617-10:03:34.814551518] [20090617-10:03:34.817172953] System Call Latency statistics in millisecs [20090617-10:03:34.820010076] ===== [20090617-10:03:34.822650133] Min Avg Max Total Calls [20090617-10:03:34.825298322] ======== ======== ======== ============ [20090617-10:03:34.827844781] [ open] 0.006000 26.731697 1356.760986 811 [20090617-10:03:34.830531841] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-10:03:34.833142450] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-10:03:34.835706251] msec_range[2] 1000.000000 - 2000.000000 : 4 [20090617-10:03:34.838178228] msec_range[3] 500.000000 - 1000.000000 : 18 [20090617-10:03:34.840771450] msec_range[4] 200.000000 - 500.000000 : 7 [20090617-10:03:34.843387151] msec_range[5] 100.000000 - 200.000000 : 3 [20090617-10:03:34.846080686] msec_range[6] 50.000000 - 100.000000 : 3 [20090617-10:03:34.848662092] msec_range[7] 20.000000 - 50.000000 : 1 [20090617-10:03:34.851370128] msec_range[8] 10.000000 - 20.000000 : 1 [20090617-10:03:34.854784753] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-10:03:34.857687827] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-10:03:34.860443896] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-10:03:34.863507867] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-10:03:34.888984289] msec_range[13] 0.200000 - 0.500000 : 0 [20090617-10:03:34.891680596] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-10:03:34.894282373] msec_range[15] 0.050000 - 0.100000 : 326 [20090617-10:03:34.897358191] msec_range[16] 0.020000 - 0.050000 : 412 [20090617-10:03:34.900147228] msec_range[17] 0.010000 - 0.020000 : 5 [20090617-10:03:34.902986826] msec_range[18] 0.000000 - 0.010000 : 31 [20090617-10:03:34.905740124] [20090617-10:03:34.908827035] [ read] 0.001000 1.344735 4823.178223 7266560 [20090617-10:03:34.911992301] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-10:03:34.914852949] msec_range[1] 2000.000000 - 5000.000000 : 264 [20090617-10:03:34.917817009] msec_range[2] 1000.000000 - 2000.000000 : 1494 [20090617-10:03:34.920753679] msec_range[3] 500.000000 - 1000.000000 : 8992 [20090617-10:03:34.923524411] msec_range[4] 200.000000 - 500.000000 : 986 [20090617-10:03:34.926172178] msec_range[5] 100.000000 - 200.000000 : 123 [20090617-10:03:34.929255756] msec_range[6] 50.000000 - 100.000000 : 133 [20090617-10:03:34.932318824] msec_range[7] 20.000000 - 50.000000 : 98 [20090617-10:03:34.935132391] msec_range[8] 10.000000 - 20.000000 : 84 [20090617-10:03:34.938077203] msec_range[9] 5.000000 - 10.000000 : 4596 [20090617-10:03:34.940836401] msec_range[10] 2.000000 - 5.000000 : 35820 [20090617-10:03:34.943538406] msec_range[11] 1.000000 - 2.000000 : 195 [20090617-10:03:34.946365539] msec_range[12] 0.500000 - 1.000000 : 162 [20090617-10:03:34.949646812] msec_range[13] 0.200000 - 0.500000 : 352 [20090617-10:03:34.952638989] msec_range[14] 0.100000 - 0.200000 : 469 [20090617-10:03:34.955657026] msec_range[15] 0.050000 - 0.100000 : 211 [20090617-10:03:34.958557108] msec_range[16] 0.020000 - 0.050000 : 2012 [20090617-10:03:34.961273833] msec_range[17] 0.010000 - 0.020000 : 187000 [20090617-10:03:34.964034759] msec_range[18] 0.000000 - 0.010000 : 7023569 [20090617-10:03:34.966967967] [20090617-10:03:34.969702790] [ close] 0.002000 0.007736 0.018000 811 [20090617-10:03:34.972211797] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-10:03:34.974813130] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-10:03:34.977506173] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-10:03:34.980152024] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-10:03:34.982655199] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-10:03:34.985260899] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-10:03:34.987877538] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-10:03:34.990528391] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-10:03:34.993063863] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-10:03:34.995642587] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-10:03:34.998226322] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-10:03:35.000879358] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-10:03:35.003391665] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-10:03:35.006064093] msec_range[13] 0.200000 - 0.500000 : 0 [20090617-10:03:35.008972933] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-10:03:35.011743686] msec_range[15] 0.050000 - 0.100000 : 0 [20090617-10:03:35.014586203] msec_range[16] 0.020000 - 0.050000 : 0 [20090617-10:03:35.017325874] msec_range[17] 0.010000 - 0.020000 : 115 [20090617-10:03:35.020019418] msec_range[18] 0.000000 - 0.010000 : 696 [20090617-10:03:35.022578705] [20090617-10:03:35.025014908] [20090617-10:03:35.027661221] [20090617-10:03:35.030347592] [20090617-10:03:35.032806679] 1.1% User Time [20090617-10:03:35.035399985] 18.8% System Time [20090617-10:03:35.038336047] 20.0% CPU Utilization [20090617-10:03:35.040971692] Profilers reporting [20090617-10:03:44.993805247] Profilers postprocessing [20090617-10:03:45.222425614] Processing File : iostat.001 [20090617-10:03:45.224852538] Discovered iostat_interval=[5] [20090617-10:03:45.982217187] Processing Directory : sar.breakout.001 [20090617-10:03:45.984561477] Discovered sar_interval=[5] [20090617-10:03:46.158561712] Processing File : mpstat.001 [20090617-10:03:46.160935200] Discovered mpstat_interval=[5] [20090617-10:03:47.298745047] Stopping profiling. [20090617-10:03:47.303345431] Killing daemon. [20090617-10:03:48.525386479] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0032.09-06-17_09.58.13/analysis/oprofile.001 [20090617-10:03:48.527838338] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0032.09-06-17_09.58.13/analysis/oprofile-brief.001 [20090617-10:03:49.590927624] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-06-17_0940/btrfs-newformat-6-17' [20090617-10:03:51.509540683] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090617-10:03:53.969651377] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090617-10:03:54.233511894] PROCESSING COMMAND : 'run random_reads__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb num_threads=1' [20090617-10:03:54.280135876] new log requested [20090617-10:03:54.310098198] Running command ffsb [20090617-10:04:03.231841124] 06/17/2009-10:04:03 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb Succeeded [20090617-10:04:03.243021114] Importing argument : num_threads=1 [20090617-10:04:03.271177021] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090617-10:04:03.350637796] FFSB version 6.0-RC2.1 started [20090617-10:04:03.352746950] [20090617-10:04:03.354993654] benchmark time = 300 [20090617-10:04:03.357152289] ThreadGroup 0 [20090617-10:04:03.359181601] ================ [20090617-10:04:03.361046536] num_threads = 1 [20090617-10:04:03.363008253] [20090617-10:04:03.364891518] read_random = on [20090617-10:04:03.366828271] read_size = 1048576 (1MB) [20090617-10:04:03.368679881] read_blocksize = 4096 (4KB) [20090617-10:04:03.370608710] read_skip = off [20090617-10:04:03.372476214] read_skipsize = 0 (0B) [20090617-10:04:03.374382599] [20090617-10:04:03.376219975] write_random = off [20090617-10:04:03.378173714] write_size = 0 (0B) [20090617-10:04:03.380067041] fsync_file = 0 [20090617-10:04:03.381958753] write_blocksize = 0 (0B) [20090617-10:04:03.383821135] wait time = 0 [20090617-10:04:03.385748196] [20090617-10:04:03.387754332] op weights [20090617-10:04:03.389684938] read = 1 (100.00%) [20090617-10:04:03.391519880] readall = 0 (0.00%) [20090617-10:04:03.393456789] write = 0 (0.00%) [20090617-10:04:03.395325748] create = 0 (0.00%) [20090617-10:04:03.397223305] append = 0 (0.00%) [20090617-10:04:03.399050734] delete = 0 (0.00%) [20090617-10:04:03.400986543] metaop = 0 (0.00%) [20090617-10:04:03.402853913] createdir = 0 (0.00%) [20090617-10:04:03.404740989] stat = 0 (0.00%) [20090617-10:04:03.406584830] writeall = 0 (0.00%) [20090617-10:04:03.408510188] writeall_fsync = 0 (0.00%) [20090617-10:04:03.410676523] open_close = 0 (0.00%) [20090617-10:04:03.412977218] write_fsync = 0 (0.00%) [20090617-10:04:03.414934114] create_fsync = 0 (0.00%) [20090617-10:04:03.417255311] append_fsync = 0 (0.00%) [20090617-10:04:03.419273623] [20090617-10:04:03.421204687] FileSystem /mnt/ffsb1 [20090617-10:04:03.423058572] ========== [20090617-10:04:03.424982833] num_dirs = 0 [20090617-10:04:03.426846848] starting files = 1024 [20090617-10:04:03.428769928] [20090617-10:04:03.430565366] min file size = 36700160 (35MB) [20090617-10:04:03.432540110] max file size = 36700160 (35MB) [20090617-10:04:03.434447481] directio = off [20090617-10:04:03.436347667] alignedio = on [20090617-10:04:03.438186069] bufferedio = off [20090617-10:04:03.440131680] [20090617-10:04:03.441979889] aging is off [20090617-10:04:03.443891331] current utilization = 51.26% [20090617-10:04:03.445659860] [20090617-10:04:03.447626958] checking existing fs: /mnt/ffsb1 [20090617-10:04:03.874910843] fs setup took 0 secs [20090617-10:04:05.082147843] Syncing()...1 sec [20090617-10:04:05.084422833] Starting Actual Benchmark At: Wed Jun 17 10:04:05 2009 [20090617-10:04:05.098717672] [20090617-10:09:06.217291922] Syncing()...0 sec [20090617-10:09:06.220596380] FFSB benchmark finished at: Wed Jun 17 10:09:06 2009 [20090617-10:09:06.223949100] [20090617-10:09:06.227098945] Results: [20090617-10:09:06.244178901] Benchmark took 301.13 sec [20090617-10:09:06.246827097] [20090617-10:09:06.249537677] Total Results [20090617-10:09:06.270683811] =============== [20090617-10:09:06.273749172] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090617-10:09:06.276675298] ======= ============ ========= ======= =========== ========== [20090617-10:09:06.279717880] read : 100352 333.25 100.000% 100.000% 1.3MB/sec [20090617-10:09:06.283680160] - [20090617-10:09:06.286787440] 333.25 Transactions per Second [20090617-10:09:06.290282188] [20090617-10:09:06.295586188] Throughput Results [20090617-10:09:06.313728790] =================== [20090617-10:09:06.316843173] Read Throughput: 1.3MB/sec [20090617-10:09:06.319791271] [20090617-10:09:06.322902027] System Call Latency statistics in millisecs [20090617-10:09:06.327940040] ===== [20090617-10:09:06.331048172] Min Avg Max Total Calls [20090617-10:09:06.334341957] ======== ======== ======== ============ [20090617-10:09:06.337234185] [ open] 0.011000 0.016503 0.036000 392 [20090617-10:09:06.340259714] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-10:09:06.343309599] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-10:09:06.355031905] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-10:09:06.359206129] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-10:09:06.362500495] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-10:09:06.365917744] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-10:09:06.370008946] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-10:09:06.373199999] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-10:09:06.377059179] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-10:09:06.380034942] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-10:09:06.383034581] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-10:09:06.386897043] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-10:09:06.389845409] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-10:09:06.392929432] msec_range[13] 0.200000 - 0.500000 : 0 [20090617-10:09:06.396607429] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-10:09:06.399622463] msec_range[15] 0.050000 - 0.100000 : 0 [20090617-10:09:06.402636356] msec_range[16] 0.020000 - 0.050000 : 77 [20090617-10:09:06.405750361] msec_range[17] 0.010000 - 0.020000 : 315 [20090617-10:09:06.408953947] msec_range[18] 0.000000 - 0.010000 : 0 [20090617-10:09:06.411737831] [20090617-10:09:06.414994228] [ read] 0.002000 2.993790 100.441002 100352 [20090617-10:09:06.418055558] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-10:09:06.421036961] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-10:09:06.424155828] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-10:09:06.427240019] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-10:09:06.430338709] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-10:09:06.433512970] msec_range[5] 100.000000 - 200.000000 : 1 [20090617-10:09:06.436640436] msec_range[6] 50.000000 - 100.000000 : 3 [20090617-10:09:06.441862050] msec_range[7] 20.000000 - 50.000000 : 91 [20090617-10:09:06.445548431] msec_range[8] 10.000000 - 20.000000 : 2428 [20090617-10:09:06.448565576] msec_range[9] 5.000000 - 10.000000 : 1085 [20090617-10:09:06.451736572] msec_range[10] 2.000000 - 5.000000 : 63597 [20090617-10:09:06.454633764] msec_range[11] 1.000000 - 2.000000 : 20739 [20090617-10:09:06.457532661] msec_range[12] 0.500000 - 1.000000 : 460 [20090617-10:09:06.460933896] msec_range[13] 0.200000 - 0.500000 : 9884 [20090617-10:09:06.463924550] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-10:09:06.467320456] msec_range[15] 0.050000 - 0.100000 : 0 [20090617-10:09:06.470259781] msec_range[16] 0.020000 - 0.050000 : 4 [20090617-10:09:06.472999845] msec_range[17] 0.010000 - 0.020000 : 148 [20090617-10:09:06.476041098] msec_range[18] 0.000000 - 0.010000 : 1912 [20090617-10:09:06.478743885] [20090617-10:09:06.481316481] [ lseek] 0.000000 0.001537 0.021000 100352 [20090617-10:09:06.484653126] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-10:09:06.487399574] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-10:09:06.490777295] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-10:09:06.494215366] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-10:09:06.497472051] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-10:09:06.500430328] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-10:09:06.503556235] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-10:09:06.506462439] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-10:09:06.509277473] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-10:09:06.512291260] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-10:09:06.515063156] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-10:09:06.518133620] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-10:09:06.520848939] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-10:09:06.523718989] msec_range[13] 0.200000 - 0.500000 : 0 [20090617-10:09:06.526553087] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-10:09:06.529525972] msec_range[15] 0.050000 - 0.100000 : 0 [20090617-10:09:06.532344731] msec_range[16] 0.020000 - 0.050000 : 1 [20090617-10:09:06.537269751] msec_range[17] 0.010000 - 0.020000 : 46 [20090617-10:09:06.540187191] msec_range[18] 0.000000 - 0.010000 : 100305 [20090617-10:09:06.543656903] [20090617-10:09:06.546763924] [ close] 0.003000 0.005242 0.016000 392 [20090617-10:09:06.549668714] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-10:09:06.552550198] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-10:09:06.555478066] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-10:09:06.558429375] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-10:09:06.561600125] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-10:09:06.564571053] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-10:09:06.567462844] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-10:09:06.570328780] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-10:09:06.572971704] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-10:09:06.575545027] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-10:09:06.578262115] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-10:09:06.581231563] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-10:09:06.584126345] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-10:09:06.586658937] msec_range[13] 0.200000 - 0.500000 : 0 [20090617-10:09:06.589473190] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-10:09:06.592252760] msec_range[15] 0.050000 - 0.100000 : 0 [20090617-10:09:06.594933133] msec_range[16] 0.020000 - 0.050000 : 0 [20090617-10:09:06.597689266] msec_range[17] 0.010000 - 0.020000 : 22 [20090617-10:09:06.600535955] msec_range[18] 0.000000 - 0.010000 : 370 [20090617-10:09:06.603173239] [20090617-10:09:06.605833783] [20090617-10:09:06.608585068] [20090617-10:09:06.611482936] [20090617-10:09:06.614185232] 0.1% User Time [20090617-10:09:06.616851162] 1.6% System Time [20090617-10:09:06.619519125] 1.6% CPU Utilization [20090617-10:09:06.622038279] Profilers reporting [20090617-10:09:06.624815635] /autobench/scripts/doprofilers: line 2: 2903 Terminated ${CMDS[$i]} [20090617-10:09:06.627452663] /autobench/scripts/doprofilers: line 2: 2907 Terminated ${CMDS[$i]} [20090617-10:09:06.630053143] /autobench/scripts/doprofilers: line 2: 2941 Terminated ${CMDS[$i]} [20090617-10:09:15.026152770] Profilers postprocessing [20090617-10:09:15.120031604] Processing File : iostat.001 [20090617-10:09:15.122273305] Discovered iostat_interval=[5] [20090617-10:09:15.844984527] Processing Directory : sar.breakout.001 [20090617-10:09:15.847368779] Discovered sar_interval=[5] [20090617-10:09:16.012865887] Processing File : mpstat.001 [20090617-10:09:16.015183530] Discovered mpstat_interval=[5] [20090617-10:09:17.155850479] Stopping profiling. [20090617-10:09:17.162040965] Killing daemon. [20090617-10:09:18.335312848] Processing File : /autobench/logs/ffsb.random_reads__threads_0001.09-06-17_10.03.54/analysis/oprofile.001 [20090617-10:09:18.337746556] Processing File : /autobench/logs/ffsb.random_reads__threads_0001.09-06-17_10.03.54/analysis/oprofile-brief.001 [20090617-10:09:18.835550082] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-06-17_0940/btrfs-newformat-6-17' [20090617-10:09:20.153498519] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090617-10:09:20.708943926] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090617-10:09:20.957940313] PROCESSING COMMAND : 'run random_reads__threads_0008 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb num_threads=8' [20090617-10:09:21.004442769] new log requested [20090617-10:09:21.034411365] Running command ffsb [20090617-10:09:29.063173851] 06/17/2009-10:09:29 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb Succeeded [20090617-10:09:29.073781901] Importing argument : num_threads=8 [20090617-10:09:29.101273324] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090617-10:09:29.172073968] FFSB version 6.0-RC2.1 started [20090617-10:09:29.174098426] [20090617-10:09:29.205059196] benchmark time = 300 [20090617-10:09:29.207555031] ThreadGroup 0 [20090617-10:09:29.209595994] ================ [20090617-10:09:29.211885249] num_threads = 8 [20090617-10:09:29.214039230] [20090617-10:09:29.216032745] read_random = on [20090617-10:09:29.217922611] read_size = 1048576 (1MB) [20090617-10:09:29.219881851] read_blocksize = 4096 (4KB) [20090617-10:09:29.221762694] read_skip = off [20090617-10:09:29.223740141] read_skipsize = 0 (0B) [20090617-10:09:29.225619278] [20090617-10:09:29.227551144] write_random = off [20090617-10:09:29.229456995] write_size = 0 (0B) [20090617-10:09:29.231391115] fsync_file = 0 [20090617-10:09:29.233296097] write_blocksize = 0 (0B) [20090617-10:09:29.235241674] wait time = 0 [20090617-10:09:29.237113316] [20090617-10:09:29.239050724] op weights [20090617-10:09:29.240908524] read = 1 (100.00%) [20090617-10:09:29.242839195] readall = 0 (0.00%) [20090617-10:09:29.244708968] write = 0 (0.00%) [20090617-10:09:29.246643247] create = 0 (0.00%) [20090617-10:09:29.248506464] append = 0 (0.00%) [20090617-10:09:29.250423224] delete = 0 (0.00%) [20090617-10:09:29.252288007] metaop = 0 (0.00%) [20090617-10:09:29.254240866] createdir = 0 (0.00%) [20090617-10:09:29.256171455] stat = 0 (0.00%) [20090617-10:09:29.258108812] writeall = 0 (0.00%) [20090617-10:09:29.259915313] writeall_fsync = 0 (0.00%) [20090617-10:09:29.261879905] open_close = 0 (0.00%) [20090617-10:09:29.263736785] write_fsync = 0 (0.00%) [20090617-10:09:29.265667935] create_fsync = 0 (0.00%) [20090617-10:09:29.267524056] append_fsync = 0 (0.00%) [20090617-10:09:29.269478012] [20090617-10:09:29.271314026] FileSystem /mnt/ffsb1 [20090617-10:09:29.273163910] ========== [20090617-10:09:29.275024758] num_dirs = 0 [20090617-10:09:29.276929815] starting files = 1024 [20090617-10:09:29.278865095] [20090617-10:09:29.280760399] min file size = 36700160 (35MB) [20090617-10:09:29.282745217] max file size = 36700160 (35MB) [20090617-10:09:29.284632421] directio = off [20090617-10:09:29.286584618] alignedio = on [20090617-10:09:29.288466165] bufferedio = off [20090617-10:09:29.290372497] [20090617-10:09:29.292222889] aging is off [20090617-10:09:29.294185359] current utilization = 51.26% [20090617-10:09:29.296050835] [20090617-10:09:29.297918646] checking existing fs: /mnt/ffsb1 [20090617-10:09:29.645602846] fs setup took 0 secs [20090617-10:09:30.947270789] Syncing()...1 sec [20090617-10:09:30.949601401] Starting Actual Benchmark At: Wed Jun 17 10:09:30 2009 [20090617-10:09:30.963639967] [20090617-10:14:35.164753708] Syncing()...0 sec [20090617-10:14:35.168040925] FFSB benchmark finished at: Wed Jun 17 10:14:35 2009 [20090617-10:14:35.171194484] [20090617-10:14:35.174250175] Results: [20090617-10:14:35.191657334] Benchmark took 304.22 sec [20090617-10:14:35.194604239] [20090617-10:14:35.197238452] Total Results [20090617-10:14:35.214565751] =============== [20090617-10:14:35.218021745] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090617-10:14:35.221345520] ======= ============ ========= ======= =========== ========== [20090617-10:14:35.224411923] read : 117760 387.09 100.000% 100.000% 1.51MB/sec [20090617-10:14:35.228751217] - [20090617-10:14:35.232120289] 387.09 Transactions per Second [20090617-10:14:35.235050363] [20090617-10:14:35.238522523] Throughput Results [20090617-10:14:35.256725810] =================== [20090617-10:14:35.259786713] Read Throughput: 1.51MB/sec [20090617-10:14:35.263221644] [20090617-10:14:35.266472009] System Call Latency statistics in millisecs [20090617-10:14:35.271169880] ===== [20090617-10:14:35.274297458] Min Avg Max Total Calls [20090617-10:14:35.277912285] ======== ======== ======== ============ [20090617-10:14:35.281182803] [ open] 0.007000 0.020491 0.044000 460 [20090617-10:14:35.284798612] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-10:14:35.290427309] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-10:14:35.293563479] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-10:14:35.296512222] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-10:14:35.299406332] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-10:14:35.302220337] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-10:14:35.306192193] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-10:14:35.309146019] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-10:14:35.312268611] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-10:14:35.316412502] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-10:14:35.320726797] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-10:14:35.323636586] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-10:14:35.326451003] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-10:14:35.329351840] msec_range[13] 0.200000 - 0.500000 : 0 [20090617-10:14:35.332591824] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-10:14:35.335776381] msec_range[15] 0.050000 - 0.100000 : 0 [20090617-10:14:35.339643342] msec_range[16] 0.020000 - 0.050000 : 245 [20090617-10:14:35.343477628] msec_range[17] 0.010000 - 0.020000 : 194 [20090617-10:14:35.347393690] msec_range[18] 0.000000 - 0.010000 : 21 [20090617-10:14:35.350700809] [20090617-10:14:35.353642547] [ read] 0.002000 20.559112 2102.063965 117760 [20090617-10:14:35.356681248] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-10:14:35.359915707] msec_range[1] 2000.000000 - 5000.000000 : 7 [20090617-10:14:35.362954627] msec_range[2] 1000.000000 - 2000.000000 : 29 [20090617-10:14:35.365853162] msec_range[3] 500.000000 - 1000.000000 : 18 [20090617-10:14:35.368699643] msec_range[4] 200.000000 - 500.000000 : 606 [20090617-10:14:35.371822919] msec_range[5] 100.000000 - 200.000000 : 3325 [20090617-10:14:35.374872262] msec_range[6] 50.000000 - 100.000000 : 8792 [20090617-10:14:35.380220792] msec_range[7] 20.000000 - 50.000000 : 19205 [20090617-10:14:35.383372999] msec_range[8] 10.000000 - 20.000000 : 17861 [20090617-10:14:35.386461354] msec_range[9] 5.000000 - 10.000000 : 17864 [20090617-10:14:35.390194568] msec_range[10] 2.000000 - 5.000000 : 33367 [20090617-10:14:35.393044547] msec_range[11] 1.000000 - 2.000000 : 13279 [20090617-10:14:35.396237856] msec_range[12] 0.500000 - 1.000000 : 466 [20090617-10:14:35.399157016] msec_range[13] 0.200000 - 0.500000 : 474 [20090617-10:14:35.402287452] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-10:14:35.405502308] msec_range[15] 0.050000 - 0.100000 : 0 [20090617-10:14:35.410501314] msec_range[16] 0.020000 - 0.050000 : 4 [20090617-10:14:35.413871593] msec_range[17] 0.010000 - 0.020000 : 408 [20090617-10:14:35.420357446] msec_range[18] 0.000000 - 0.010000 : 2055 [20090617-10:14:35.423782870] [20090617-10:14:35.427293403] [ lseek] 0.000000 0.001631 0.197000 117760 [20090617-10:14:35.430547503] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-10:14:35.436136248] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-10:14:35.439840925] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-10:14:35.443075595] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-10:14:35.447580484] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-10:14:35.451334235] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-10:14:35.454462495] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-10:14:35.458649955] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-10:14:35.461855250] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-10:14:35.464974252] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-10:14:35.468057888] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-10:14:35.470958799] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-10:14:35.476553591] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-10:14:35.479604373] msec_range[13] 0.200000 - 0.500000 : 0 [20090617-10:14:35.482507475] msec_range[14] 0.100000 - 0.200000 : 2 [20090617-10:14:35.485487683] msec_range[15] 0.050000 - 0.100000 : 0 [20090617-10:14:35.488461740] msec_range[16] 0.020000 - 0.050000 : 3 [20090617-10:14:35.496990513] msec_range[17] 0.010000 - 0.020000 : 152 [20090617-10:14:35.500243744] msec_range[18] 0.000000 - 0.010000 : 117603 [20090617-10:14:35.503131464] [20090617-10:14:35.505931313] [ close] 0.003000 0.005963 0.017000 460 [20090617-10:14:35.508682741] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-10:14:35.511623562] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-10:14:35.514271592] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-10:14:35.517046733] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-10:14:35.519703931] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-10:14:35.522658560] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-10:14:35.525510370] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-10:14:35.528326739] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-10:14:35.531110412] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-10:14:35.533740334] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-10:14:35.536307931] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-10:14:35.538797950] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-10:14:35.541463268] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-10:14:35.544007607] msec_range[13] 0.200000 - 0.500000 : 0 [20090617-10:14:35.546638530] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-10:14:35.549254378] msec_range[15] 0.050000 - 0.100000 : 0 [20090617-10:14:35.551791392] msec_range[16] 0.020000 - 0.050000 : 0 [20090617-10:14:35.554380448] msec_range[17] 0.010000 - 0.020000 : 56 [20090617-10:14:35.556893881] msec_range[18] 0.000000 - 0.010000 : 404 [20090617-10:14:35.559514227] [20090617-10:14:35.562011197] [20090617-10:14:35.564646283] [20090617-10:14:35.567253633] [20090617-10:14:35.570002549] 0.1% User Time [20090617-10:14:35.572685790] 2.2% System Time [20090617-10:14:35.575270973] 2.3% CPU Utilization [20090617-10:14:35.577965522] Profilers reporting [20090617-10:14:35.580546678] /autobench/scripts/doprofilers: line 2: 9110 Terminated ${CMDS[$i]} [20090617-10:14:35.583255861] /autobench/scripts/doprofilers: line 2: 9128 Terminated ${CMDS[$i]} [20090617-10:14:35.585949331] /autobench/scripts/doprofilers: line 2: 9174 Terminated ${CMDS[$i]} [20090617-10:14:43.524402602] Profilers postprocessing [20090617-10:14:43.618312193] Processing File : iostat.001 [20090617-10:14:43.620832451] Discovered iostat_interval=[5] [20090617-10:14:44.321326338] Processing Directory : sar.breakout.001 [20090617-10:14:44.323670328] Discovered sar_interval=[5] [20090617-10:14:44.488742328] Processing File : mpstat.001 [20090617-10:14:44.491161569] Discovered mpstat_interval=[5] [20090617-10:14:45.631152356] Stopping profiling. [20090617-10:14:45.635632924] Killing daemon. [20090617-10:14:46.811616267] Processing File : /autobench/logs/ffsb.random_reads__threads_0008.09-06-17_10.09.21/analysis/oprofile.001 [20090617-10:14:46.813774458] Processing File : /autobench/logs/ffsb.random_reads__threads_0008.09-06-17_10.09.21/analysis/oprofile-brief.001 [20090617-10:14:47.291527699] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-06-17_0940/btrfs-newformat-6-17' [20090617-10:14:48.550143377] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090617-10:14:49.174653656] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090617-10:14:49.433439414] PROCESSING COMMAND : 'run random_reads__threads_0032 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb num_threads=32' [20090617-10:14:49.481014499] new log requested [20090617-10:14:49.510846430] Running command ffsb [20090617-10:14:57.517411348] 06/17/2009-10:14:57 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb Succeeded [20090617-10:14:57.528290457] Importing argument : num_threads=32 [20090617-10:14:57.556826476] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090617-10:14:57.626916387] FFSB version 6.0-RC2.1 started [20090617-10:14:57.629124770] [20090617-10:14:57.760306701] benchmark time = 300 [20090617-10:14:57.762615199] ThreadGroup 0 [20090617-10:14:57.764621256] ================ [20090617-10:14:57.766868087] num_threads = 32 [20090617-10:14:57.768972923] [20090617-10:14:57.770926127] read_random = on [20090617-10:14:57.772849653] read_size = 1048576 (1MB) [20090617-10:14:57.774723185] read_blocksize = 4096 (4KB) [20090617-10:14:57.776537040] read_skip = off [20090617-10:14:57.778545076] read_skipsize = 0 (0B) [20090617-10:14:57.780525655] [20090617-10:14:57.782461416] write_random = off [20090617-10:14:57.784327827] write_size = 0 (0B) [20090617-10:14:57.786348571] fsync_file = 0 [20090617-10:14:57.788172395] write_blocksize = 0 (0B) [20090617-10:14:57.790096904] wait time = 0 [20090617-10:14:57.791978562] [20090617-10:14:57.793931414] op weights [20090617-10:14:57.795810994] read = 1 (100.00%) [20090617-10:14:57.798028744] readall = 0 (0.00%) [20090617-10:14:57.800105113] write = 0 (0.00%) [20090617-10:14:57.802181432] create = 0 (0.00%) [20090617-10:14:57.804067076] append = 0 (0.00%) [20090617-10:14:57.806022090] delete = 0 (0.00%) [20090617-10:14:57.807914364] metaop = 0 (0.00%) [20090617-10:14:57.809869881] createdir = 0 (0.00%) [20090617-10:14:57.811735453] stat = 0 (0.00%) [20090617-10:14:57.813659905] writeall = 0 (0.00%) [20090617-10:14:57.815538640] writeall_fsync = 0 (0.00%) [20090617-10:14:57.817471227] open_close = 0 (0.00%) [20090617-10:14:57.819312306] write_fsync = 0 (0.00%) [20090617-10:14:57.821169470] create_fsync = 0 (0.00%) [20090617-10:14:57.823057090] append_fsync = 0 (0.00%) [20090617-10:14:57.825011975] [20090617-10:14:57.826863763] FileSystem /mnt/ffsb1 [20090617-10:14:57.828775952] ========== [20090617-10:14:57.830632999] num_dirs = 0 [20090617-10:14:57.832580987] starting files = 1024 [20090617-10:14:57.834431390] [20090617-10:14:57.836345005] min file size = 36700160 (35MB) [20090617-10:14:57.838200673] max file size = 36700160 (35MB) [20090617-10:14:57.840127996] directio = off [20090617-10:14:57.841967241] alignedio = on [20090617-10:14:57.843887415] bufferedio = off [20090617-10:14:57.845758650] [20090617-10:14:57.847697681] aging is off [20090617-10:14:57.849559362] current utilization = 51.26% [20090617-10:14:57.851487187] [20090617-10:14:57.853362196] checking existing fs: /mnt/ffsb1 [20090617-10:14:58.212198530] fs setup took 0 secs [20090617-10:14:59.556411554] Syncing()...1 sec [20090617-10:14:59.558802990] Starting Actual Benchmark At: Wed Jun 17 10:14:59 2009 [20090617-10:14:59.573616228] [20090617-10:20:11.058146451] Syncing()...0 sec [20090617-10:20:11.061390852] FFSB benchmark finished at: Wed Jun 17 10:20:11 2009 [20090617-10:20:11.064669814] [20090617-10:20:11.067714683] Results: [20090617-10:20:11.085200496] Benchmark took 311.50 sec [20090617-10:20:11.088122425] [20090617-10:20:11.090986775] Total Results [20090617-10:20:11.111208958] =============== [20090617-10:20:11.114435810] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090617-10:20:11.118832748] ======= ============ ========= ======= =========== ========== [20090617-10:20:11.122438663] read : 147968 475.02 100.000% 100.000% 1.86MB/sec [20090617-10:20:11.125427172] - [20090617-10:20:11.129047896] 475.02 Transactions per Second [20090617-10:20:11.132405490] [20090617-10:20:11.135707668] Throughput Results [20090617-10:20:11.153222735] =================== [20090617-10:20:11.156238233] Read Throughput: 1.86MB/sec [20090617-10:20:11.159265452] [20090617-10:20:11.162463671] System Call Latency statistics in millisecs [20090617-10:20:11.166260957] ===== [20090617-10:20:11.170433283] Min Avg Max Total Calls [20090617-10:20:11.173265873] ======== ======== ======== ============ [20090617-10:20:11.176447309] [ open] 0.006000 0.020573 0.049000 578 [20090617-10:20:11.180060714] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-10:20:11.182896453] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-10:20:11.185920504] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-10:20:11.188912283] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-10:20:11.192071214] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-10:20:11.195181484] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-10:20:11.198233962] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-10:20:11.202043824] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-10:20:11.204739988] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-10:20:11.207565103] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-10:20:11.210762165] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-10:20:11.214136917] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-10:20:11.217496762] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-10:20:11.220539694] msec_range[13] 0.200000 - 0.500000 : 0 [20090617-10:20:11.223520558] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-10:20:11.226325583] msec_range[15] 0.050000 - 0.100000 : 0 [20090617-10:20:11.229204301] msec_range[16] 0.020000 - 0.050000 : 311 [20090617-10:20:11.232152961] msec_range[17] 0.010000 - 0.020000 : 214 [20090617-10:20:11.236518157] msec_range[18] 0.000000 - 0.010000 : 53 [20090617-10:20:11.239765702] [20090617-10:20:11.243869650] [ read] 0.002000 66.345517 2308.935059 147968 [20090617-10:20:11.246936002] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-10:20:11.250137125] msec_range[1] 2000.000000 - 5000.000000 : 26 [20090617-10:20:11.253554402] msec_range[2] 1000.000000 - 2000.000000 : 428 [20090617-10:20:11.256464008] msec_range[3] 500.000000 - 1000.000000 : 2407 [20090617-10:20:11.259440192] msec_range[4] 200.000000 - 500.000000 : 9811 [20090617-10:20:11.262590884] msec_range[5] 100.000000 - 200.000000 : 12899 [20090617-10:20:11.265443447] msec_range[6] 50.000000 - 100.000000 : 17138 [20090617-10:20:11.269899094] msec_range[7] 20.000000 - 50.000000 : 30456 [20090617-10:20:11.273070331] msec_range[8] 10.000000 - 20.000000 : 25875 [20090617-10:20:11.276104332] msec_range[9] 5.000000 - 10.000000 : 21847 [20090617-10:20:11.279193293] msec_range[10] 2.000000 - 5.000000 : 18509 [20090617-10:20:11.282257400] msec_range[11] 1.000000 - 2.000000 : 5153 [20090617-10:20:11.285450281] msec_range[12] 0.500000 - 1.000000 : 73 [20090617-10:20:11.288433767] msec_range[13] 0.200000 - 0.500000 : 30 [20090617-10:20:11.291488292] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-10:20:11.294648307] msec_range[15] 0.050000 - 0.100000 : 0 [20090617-10:20:11.297798975] msec_range[16] 0.020000 - 0.050000 : 14 [20090617-10:20:11.300831431] msec_range[17] 0.010000 - 0.020000 : 659 [20090617-10:20:11.304378294] msec_range[18] 0.000000 - 0.010000 : 2643 [20090617-10:20:11.307881488] [20090617-10:20:11.311105176] [ lseek] 0.000000 0.001656 0.202000 147968 [20090617-10:20:11.314219469] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-10:20:11.317286905] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-10:20:11.320956376] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-10:20:11.324457738] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-10:20:11.327711544] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-10:20:11.333178963] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-10:20:11.338884528] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-10:20:11.342064402] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-10:20:11.345908251] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-10:20:11.348864637] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-10:20:11.351479931] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-10:20:11.354500910] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-10:20:11.357489920] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-10:20:11.360428797] msec_range[13] 0.200000 - 0.500000 : 1 [20090617-10:20:11.365782460] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-10:20:11.369322283] msec_range[15] 0.050000 - 0.100000 : 0 [20090617-10:20:11.372164901] msec_range[16] 0.020000 - 0.050000 : 1 [20090617-10:20:11.375263948] msec_range[17] 0.010000 - 0.020000 : 204 [20090617-10:20:11.378543681] msec_range[18] 0.000000 - 0.010000 : 147762 [20090617-10:20:11.381633778] [20090617-10:20:11.384566676] [ close] 0.002000 0.005682 0.019000 578 [20090617-10:20:11.387455461] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-10:20:11.390612282] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-10:20:11.393378672] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-10:20:11.396275597] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-10:20:11.399187190] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-10:20:11.401908951] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-10:20:11.404535292] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-10:20:11.407199718] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-10:20:11.409845354] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-10:20:11.412411136] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-10:20:11.415311787] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-10:20:11.418137297] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-10:20:11.421041271] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-10:20:11.423813027] msec_range[13] 0.200000 - 0.500000 : 0 [20090617-10:20:11.426554704] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-10:20:11.429243929] msec_range[15] 0.050000 - 0.100000 : 0 [20090617-10:20:11.431884944] msec_range[16] 0.020000 - 0.050000 : 0 [20090617-10:20:11.434529693] msec_range[17] 0.010000 - 0.020000 : 76 [20090617-10:20:11.437116269] msec_range[18] 0.000000 - 0.010000 : 502 [20090617-10:20:11.439764678] [20090617-10:20:11.442383092] [20090617-10:20:11.444964351] [20090617-10:20:11.447540855] [20090617-10:20:11.450100634] 0.1% User Time [20090617-10:20:11.452672378] 2.8% System Time [20090617-10:20:11.455203967] 2.9% CPU Utilization [20090617-10:20:11.457885274] Profilers reporting [20090617-10:20:11.460590792] /autobench/scripts/doprofilers: line 2: 15346 Terminated ${CMDS[$i]} [20090617-10:20:11.463092647] /autobench/scripts/doprofilers: line 2: 15394 Terminated ${CMDS[$i]} [20090617-10:20:20.287380981] Profilers postprocessing [20090617-10:20:20.380175300] Processing File : iostat.001 [20090617-10:20:20.382406928] Discovered iostat_interval=[5] [20090617-10:20:21.098195506] Processing Directory : sar.breakout.001 [20090617-10:20:21.100307686] Discovered sar_interval=[5] [20090617-10:20:21.269267348] Processing File : mpstat.001 [20090617-10:20:21.271666580] Discovered mpstat_interval=[5] [20090617-10:20:22.410011231] Stopping profiling. [20090617-10:20:22.416954559] Killing daemon. [20090617-10:20:23.581952412] Processing File : /autobench/logs/ffsb.random_reads__threads_0032.09-06-17_10.14.49/analysis/oprofile.001 [20090617-10:20:23.584301583] Processing File : /autobench/logs/ffsb.random_reads__threads_0032.09-06-17_10.14.49/analysis/oprofile-brief.001 [20090617-10:20:24.070807995] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-06-17_0940/btrfs-newformat-6-17' [20090617-10:20:25.338744694] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090617-10:20:26.149364147] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090617-10:20:26.438487661] PROCESSING COMMAND : 'run random_writes__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb num_threads=1' [20090617-10:20:26.484226854] new log requested [20090617-10:20:26.513984072] Running command ffsb [20090617-10:20:34.572744717] 06/17/2009-10:20:34 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb Succeeded [20090617-10:20:34.583558187] Importing argument : num_threads=1 [20090617-10:20:34.612681787] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090617-10:20:34.682494943] FFSB version 6.0-RC2.1 started [20090617-10:20:34.684715815] [20090617-10:20:34.686992883] benchmark time = 300 [20090617-10:20:34.689149027] ThreadGroup 0 [20090617-10:20:34.691419282] ================ [20090617-10:20:34.693377816] num_threads = 1 [20090617-10:20:34.695685620] [20090617-10:20:34.697835220] read_random = off [20090617-10:20:34.699725563] read_size = 0 (0B) [20090617-10:20:34.701712357] read_blocksize = 0 (0B) [20090617-10:20:34.703784142] read_skip = off [20090617-10:20:34.705861379] read_skipsize = 0 (0B) [20090617-10:20:34.707686525] [20090617-10:20:34.709634302] write_random = on [20090617-10:20:34.711537503] write_size = 1048576 (1MB) [20090617-10:20:34.713506117] fsync_file = 0 [20090617-10:20:34.715379963] write_blocksize = 4096 (4KB) [20090617-10:20:34.717328402] wait time = 0 [20090617-10:20:34.719204919] [20090617-10:20:34.721165780] op weights [20090617-10:20:34.722997633] read = 0 (0.00%) [20090617-10:20:34.724915128] readall = 0 (0.00%) [20090617-10:20:34.726764604] write = 1 (100.00%) [20090617-10:20:34.728690733] create = 0 (0.00%) [20090617-10:20:34.730521574] append = 0 (0.00%) [20090617-10:20:34.732440931] delete = 0 (0.00%) [20090617-10:20:34.734292263] metaop = 0 (0.00%) [20090617-10:20:34.736217666] createdir = 0 (0.00%) [20090617-10:20:34.738046108] stat = 0 (0.00%) [20090617-10:20:34.739965018] writeall = 0 (0.00%) [20090617-10:20:34.741810756] writeall_fsync = 0 (0.00%) [20090617-10:20:34.743735480] open_close = 0 (0.00%) [20090617-10:20:34.745575400] write_fsync = 0 (0.00%) [20090617-10:20:34.747511454] create_fsync = 0 (0.00%) [20090617-10:20:34.749388033] append_fsync = 0 (0.00%) [20090617-10:20:34.751300574] [20090617-10:20:34.753136938] FileSystem /mnt/ffsb1 [20090617-10:20:34.755035586] ========== [20090617-10:20:34.756857159] num_dirs = 0 [20090617-10:20:34.758727020] starting files = 1024 [20090617-10:20:34.760580399] [20090617-10:20:34.762488068] min file size = 36700160 (35MB) [20090617-10:20:34.764329868] max file size = 36700160 (35MB) [20090617-10:20:34.766230662] directio = off [20090617-10:20:34.768078614] alignedio = on [20090617-10:20:34.770007705] bufferedio = off [20090617-10:20:34.771835572] [20090617-10:20:34.773741304] aging is off [20090617-10:20:34.775572226] current utilization = 51.26% [20090617-10:20:34.777515489] [20090617-10:20:34.779370613] creating new fileset /mnt/ffsb1 [20090617-10:27:04.722448165] fs setup took 389 secs [20090617-10:27:12.051369974] Syncing()...7 sec [20090617-10:27:12.053881050] Starting Actual Benchmark At: Wed Jun 17 10:27:12 2009 [20090617-10:27:12.152938482] [20090617-10:32:32.963457716] Syncing()...9 sec [20090617-10:32:32.979211864] FFSB benchmark finished at: Wed Jun 17 10:32:32 2009 [20090617-10:32:32.982706454] [20090617-10:32:32.985985673] Results: [20090617-10:32:33.009907884] Benchmark took 320.79 sec [20090617-10:32:33.012417686] [20090617-10:32:33.015493329] Total Results [20090617-10:32:33.032094132] =============== [20090617-10:32:33.035146490] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090617-10:32:33.038258446] ======= ============ ========= ======= =========== ========== [20090617-10:32:33.041251356] write : 1661440 5179.22 100.000% 100.000% 20.2MB/sec [20090617-10:32:33.044034396] - [20090617-10:32:33.046809062] 5179.22 Transactions per Second [20090617-10:32:33.049730285] [20090617-10:32:33.052768825] Throughput Results [20090617-10:32:33.068918243] =================== [20090617-10:32:33.094597840] Write Throughput: 20.2MB/sec [20090617-10:32:33.097367485] [20090617-10:32:33.099887148] System Call Latency statistics in millisecs [20090617-10:32:33.102608342] ===== [20090617-10:32:33.105206377] Min Avg Max Total Calls [20090617-10:32:33.107843822] ======== ======== ======== ============ [20090617-10:32:33.110466060] [ open] 0.007000 0.014076 0.329000 6490 [20090617-10:32:33.113062208] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-10:32:33.115603290] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-10:32:33.118176821] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-10:32:33.120703516] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-10:32:33.123341086] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-10:32:33.126045426] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-10:32:33.128796490] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-10:32:33.131340650] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-10:32:33.134322381] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-10:32:33.136853335] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-10:32:33.139508739] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-10:32:33.142146052] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-10:32:33.144706998] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-10:32:33.147329508] msec_range[13] 0.200000 - 0.500000 : 1 [20090617-10:32:33.149884008] msec_range[14] 0.100000 - 0.200000 : 1 [20090617-10:32:33.153567060] msec_range[15] 0.050000 - 0.100000 : 69 [20090617-10:32:33.156422528] msec_range[16] 0.020000 - 0.050000 : 532 [20090617-10:32:33.159009687] msec_range[17] 0.010000 - 0.020000 : 5471 [20090617-10:32:33.161639335] msec_range[18] 0.000000 - 0.010000 : 416 [20090617-10:32:33.164494796] [20090617-10:32:33.167361826] [ write] 0.008000 0.185534 54088.785156 1661440 [20090617-10:32:33.170811994] msec_range[0] 5000.000000 - 10000.000000 : 3 [20090617-10:32:33.173776886] msec_range[1] 2000.000000 - 5000.000000 : 4 [20090617-10:32:33.176584869] msec_range[2] 1000.000000 - 2000.000000 : 14 [20090617-10:32:33.179296960] msec_range[3] 500.000000 - 1000.000000 : 26 [20090617-10:32:33.182240337] msec_range[4] 200.000000 - 500.000000 : 31 [20090617-10:32:33.184814926] msec_range[5] 100.000000 - 200.000000 : 12 [20090617-10:32:33.187385667] msec_range[6] 50.000000 - 100.000000 : 21 [20090617-10:32:33.189866455] msec_range[7] 20.000000 - 50.000000 : 461 [20090617-10:32:33.192605015] msec_range[8] 10.000000 - 20.000000 : 55 [20090617-10:32:33.195420166] msec_range[9] 5.000000 - 10.000000 : 39 [20090617-10:32:33.198264092] msec_range[10] 2.000000 - 5.000000 : 81 [20090617-10:32:33.201713147] msec_range[11] 1.000000 - 2.000000 : 98 [20090617-10:32:33.204432218] msec_range[12] 0.500000 - 1.000000 : 109 [20090617-10:32:33.207587865] msec_range[13] 0.200000 - 0.500000 : 808 [20090617-10:32:33.210432060] msec_range[14] 0.100000 - 0.200000 : 1580 [20090617-10:32:33.213429191] msec_range[15] 0.050000 - 0.100000 : 3675 [20090617-10:32:33.216768426] msec_range[16] 0.020000 - 0.050000 : 158562 [20090617-10:32:33.219752165] msec_range[17] 0.010000 - 0.020000 : 1491126 [20090617-10:32:33.222618919] msec_range[18] 0.000000 - 0.010000 : 4727 [20090617-10:32:33.225138608] [20090617-10:32:33.227762240] [ lseek] 0.000000 0.001034 0.254000 1661440 [20090617-10:32:33.231095043] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-10:32:33.234376707] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-10:32:33.237058891] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-10:32:33.239613104] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-10:32:33.242807939] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-10:32:33.246010294] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-10:32:33.248689635] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-10:32:33.251361668] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-10:32:33.254004073] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-10:32:33.256801828] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-10:32:33.259406666] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-10:32:33.262079021] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-10:32:33.264618923] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-10:32:33.267294417] msec_range[13] 0.200000 - 0.500000 : 3 [20090617-10:32:33.270011819] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-10:32:33.272573960] msec_range[15] 0.050000 - 0.100000 : 0 [20090617-10:32:33.275102936] msec_range[16] 0.020000 - 0.050000 : 5 [20090617-10:32:33.277805442] msec_range[17] 0.010000 - 0.020000 : 152 [20090617-10:32:33.280334864] msec_range[18] 0.000000 - 0.010000 : 1661280 [20090617-10:32:33.282843021] [20090617-10:32:33.285734669] [ close] 0.002000 0.003608 0.018000 6490 [20090617-10:32:33.288587445] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-10:32:33.291199713] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-10:32:33.293716343] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-10:32:33.296433056] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-10:32:33.299166443] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-10:32:33.301897250] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-10:32:33.304326952] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-10:32:33.307152794] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-10:32:33.309877795] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-10:32:33.312824559] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-10:32:33.315448734] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-10:32:33.318188155] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-10:32:33.320811190] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-10:32:33.323433328] msec_range[13] 0.200000 - 0.500000 : 0 [20090617-10:32:33.325962064] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-10:32:33.328646340] msec_range[15] 0.050000 - 0.100000 : 0 [20090617-10:32:33.331356680] msec_range[16] 0.020000 - 0.050000 : 0 [20090617-10:32:33.334176427] msec_range[17] 0.010000 - 0.020000 : 19 [20090617-10:32:33.337007543] msec_range[18] 0.000000 - 0.010000 : 6471 [20090617-10:32:33.339850459] [20090617-10:32:33.343209943] [20090617-10:32:33.345951760] [20090617-10:32:33.348839598] [20090617-10:32:33.353122785] 0.6% User Time [20090617-10:32:33.356432953] 13.2% System Time [20090617-10:32:33.360156038] 13.8% CPU Utilization [20090617-10:32:33.363137772] Profilers reporting [20090617-10:32:42.786875549] Profilers postprocessing [20090617-10:32:43.042855976] Processing File : iostat.001 [20090617-10:32:43.045169845] Discovered iostat_interval=[5] [20090617-10:32:43.807669385] Processing Directory : sar.breakout.001 [20090617-10:32:43.810065873] Discovered sar_interval=[5] [20090617-10:32:43.991037226] Processing File : mpstat.001 [20090617-10:32:43.993337280] Discovered mpstat_interval=[5] [20090617-10:32:45.135703874] Stopping profiling. [20090617-10:32:45.141737248] Killing daemon. [20090617-10:32:47.412898329] Processing File : /autobench/logs/ffsb.random_writes__threads_0001.09-06-17_10.20.26/analysis/oprofile.001 [20090617-10:32:47.415559159] Processing File : /autobench/logs/ffsb.random_writes__threads_0001.09-06-17_10.20.26/analysis/oprofile-brief.001 [20090617-10:32:48.517309487] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-06-17_0940/btrfs-newformat-6-17' [20090617-10:32:50.421982770] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090617-10:32:53.576504287] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090617-10:32:53.871078117] PROCESSING COMMAND : 'run random_writes__threads_0008 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb num_threads=8' [20090617-10:32:53.917938308] new log requested [20090617-10:32:53.953549251] Running command ffsb [20090617-10:33:02.900008511] 06/17/2009-10:33:02 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb Succeeded [20090617-10:33:02.911324998] Importing argument : num_threads=8 [20090617-10:33:02.939862411] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090617-10:33:03.015050867] FFSB version 6.0-RC2.1 started [20090617-10:33:03.017399977] [20090617-10:33:03.048553182] benchmark time = 300 [20090617-10:33:03.050734667] ThreadGroup 0 [20090617-10:33:03.053014737] ================ [20090617-10:33:03.055123018] num_threads = 8 [20090617-10:33:03.057154937] [20090617-10:33:03.059031028] read_random = off [20090617-10:33:03.061211074] read_size = 0 (0B) [20090617-10:33:03.063361052] read_blocksize = 0 (0B) [20090617-10:33:03.065419586] read_skip = off [20090617-10:33:03.067298456] read_skipsize = 0 (0B) [20090617-10:33:03.069262556] [20090617-10:33:03.071159467] write_random = on [20090617-10:33:03.073121342] write_size = 1048576 (1MB) [20090617-10:33:03.074994578] fsync_file = 0 [20090617-10:33:03.076951218] write_blocksize = 4096 (4KB) [20090617-10:33:03.079081997] wait time = 0 [20090617-10:33:03.081292247] [20090617-10:33:03.083324972] op weights [20090617-10:33:03.085232289] read = 0 (0.00%) [20090617-10:33:03.087370961] readall = 0 (0.00%) [20090617-10:33:03.089266859] write = 1 (100.00%) [20090617-10:33:03.091258581] create = 0 (0.00%) [20090617-10:33:03.093128310] append = 0 (0.00%) [20090617-10:33:03.095110447] delete = 0 (0.00%) [20090617-10:33:03.096988643] metaop = 0 (0.00%) [20090617-10:33:03.099001942] createdir = 0 (0.00%) [20090617-10:33:03.100869043] stat = 0 (0.00%) [20090617-10:33:03.102825401] writeall = 0 (0.00%) [20090617-10:33:03.104679445] writeall_fsync = 0 (0.00%) [20090617-10:33:03.106636725] open_close = 0 (0.00%) [20090617-10:33:03.108449093] write_fsync = 0 (0.00%) [20090617-10:33:03.110415711] create_fsync = 0 (0.00%) [20090617-10:33:03.112277852] append_fsync = 0 (0.00%) [20090617-10:33:03.114263380] [20090617-10:33:03.116151086] FileSystem /mnt/ffsb1 [20090617-10:33:03.118101950] ========== [20090617-10:33:03.119962462] num_dirs = 0 [20090617-10:33:03.121892097] starting files = 1024 [20090617-10:33:03.123759674] [20090617-10:33:03.125713165] min file size = 36700160 (35MB) [20090617-10:33:03.127700126] max file size = 36700160 (35MB) [20090617-10:33:03.129585206] directio = off [20090617-10:33:03.131612110] alignedio = on [20090617-10:33:03.133530352] bufferedio = off [20090617-10:33:03.135512460] [20090617-10:33:03.137319303] aging is off [20090617-10:33:03.139443111] current utilization = 59.69% [20090617-10:33:03.141316323] [20090617-10:33:03.143249390] creating new fileset /mnt/ffsb1 [20090617-10:45:11.329256673] fs setup took 728 secs [20090617-10:45:19.167346242] Syncing()...8 sec [20090617-10:45:19.169879239] Starting Actual Benchmark At: Wed Jun 17 10:45:19 2009 [20090617-10:45:19.281207559] [20090617-10:50:38.113528209] Syncing()...9 sec [20090617-10:50:38.162591802] FFSB benchmark finished at: Wed Jun 17 10:50:37 2009 [20090617-10:50:38.166076827] [20090617-10:50:38.169393618] Results: [20090617-10:50:38.210898436] Benchmark took 318.73 sec [20090617-10:50:38.213498190] [20090617-10:50:38.216801826] Total Results [20090617-10:50:38.233061889] =============== [20090617-10:50:38.248041401] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090617-10:50:38.250939486] ======= ============ ========= ======= =========== ========== [20090617-10:50:38.253979142] write : 1673472 5250.46 100.000% 100.000% 20.5MB/sec [20090617-10:50:38.257143742] - [20090617-10:50:38.260135115] 5250.46 Transactions per Second [20090617-10:50:38.263230583] [20090617-10:50:38.266092271] Throughput Results [20090617-10:50:38.282884554] =================== [20090617-10:50:38.286207311] Write Throughput: 20.5MB/sec [20090617-10:50:38.289077919] [20090617-10:50:38.291778187] System Call Latency statistics in millisecs [20090617-10:50:38.295171434] ===== [20090617-10:50:38.298660749] Min Avg Max Total Calls [20090617-10:50:38.302419714] ======== ======== ======== ============ [20090617-10:50:38.305415567] [ open] 0.009000 0.042610 18.163000 6537 [20090617-10:50:38.309343912] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-10:50:38.312411001] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-10:50:38.315505766] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-10:50:38.318731232] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-10:50:38.321975099] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-10:50:38.324795871] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-10:50:38.327565591] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-10:50:38.330534285] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-10:50:38.333677893] msec_range[8] 10.000000 - 20.000000 : 5 [20090617-10:50:38.336364090] msec_range[9] 5.000000 - 10.000000 : 1 [20090617-10:50:38.338962069] msec_range[10] 2.000000 - 5.000000 : 7 [20090617-10:50:38.342061743] msec_range[11] 1.000000 - 2.000000 : 1 [20090617-10:50:38.345110927] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-10:50:38.347771007] msec_range[13] 0.200000 - 0.500000 : 11 [20090617-10:50:38.350294250] msec_range[14] 0.100000 - 0.200000 : 198 [20090617-10:50:38.352972349] msec_range[15] 0.050000 - 0.100000 : 573 [20090617-10:50:38.355807265] msec_range[16] 0.020000 - 0.050000 : 2095 [20090617-10:50:38.358617190] msec_range[17] 0.010000 - 0.020000 : 3631 [20090617-10:50:38.362164195] msec_range[18] 0.000000 - 0.010000 : 15 [20090617-10:50:38.364798294] [20090617-10:50:38.367502050] [ write] 0.008000 1.409486 58347.144531 1673472 [20090617-10:50:38.370277552] msec_range[0] 5000.000000 - 10000.000000 : 39 [20090617-10:50:38.372891722] msec_range[1] 2000.000000 - 5000.000000 : 91 [20090617-10:50:38.375596376] msec_range[2] 1000.000000 - 2000.000000 : 100 [20090617-10:50:38.378236776] msec_range[3] 500.000000 - 1000.000000 : 84 [20090617-10:50:38.380796375] msec_range[4] 200.000000 - 500.000000 : 117 [20090617-10:50:38.383366303] msec_range[5] 100.000000 - 200.000000 : 261 [20090617-10:50:38.385931642] msec_range[6] 50.000000 - 100.000000 : 412 [20090617-10:50:38.388478443] msec_range[7] 20.000000 - 50.000000 : 177 [20090617-10:50:38.391106678] msec_range[8] 10.000000 - 20.000000 : 215 [20090617-10:50:38.393610846] msec_range[9] 5.000000 - 10.000000 : 97 [20090617-10:50:38.396178298] msec_range[10] 2.000000 - 5.000000 : 265 [20090617-10:50:38.398629339] msec_range[11] 1.000000 - 2.000000 : 198 [20090617-10:50:38.401171868] msec_range[12] 0.500000 - 1.000000 : 1101 [20090617-10:50:38.403697555] msec_range[13] 0.200000 - 0.500000 : 48743 [20090617-10:50:38.406256007] msec_range[14] 0.100000 - 0.200000 : 123180 [20090617-10:50:38.408721794] msec_range[15] 0.050000 - 0.100000 : 160233 [20090617-10:50:38.411188176] msec_range[16] 0.020000 - 0.050000 : 769097 [20090617-10:50:38.413812065] msec_range[17] 0.010000 - 0.020000 : 568833 [20090617-10:50:38.416401314] msec_range[18] 0.000000 - 0.010000 : 178 [20090617-10:50:38.419037402] [20090617-10:50:38.421631797] [ lseek] 0.000000 0.059711 38611.675781 1673472 [20090617-10:50:38.424426759] msec_range[0] 5000.000000 - 10000.000000 : 1 [20090617-10:50:38.427332279] msec_range[1] 2000.000000 - 5000.000000 : 6 [20090617-10:50:38.430063193] msec_range[2] 1000.000000 - 2000.000000 : 7 [20090617-10:50:38.432948213] msec_range[3] 500.000000 - 1000.000000 : 9 [20090617-10:50:38.435788863] msec_range[4] 200.000000 - 500.000000 : 7 [20090617-10:50:38.438674582] msec_range[5] 100.000000 - 200.000000 : 10 [20090617-10:50:38.442425296] msec_range[6] 50.000000 - 100.000000 : 14 [20090617-10:50:38.445839883] msec_range[7] 20.000000 - 50.000000 : 5 [20090617-10:50:38.449890367] msec_range[8] 10.000000 - 20.000000 : 7 [20090617-10:50:38.452709773] msec_range[9] 5.000000 - 10.000000 : 6 [20090617-10:50:38.455356783] msec_range[10] 2.000000 - 5.000000 : 7 [20090617-10:50:38.458124477] msec_range[11] 1.000000 - 2.000000 : 4 [20090617-10:50:38.460730265] msec_range[12] 0.500000 - 1.000000 : 3 [20090617-10:50:38.463683967] msec_range[13] 0.200000 - 0.500000 : 59 [20090617-10:50:38.466773168] msec_range[14] 0.100000 - 0.200000 : 399 [20090617-10:50:38.469732217] msec_range[15] 0.050000 - 0.100000 : 1301 [20090617-10:50:38.473273801] msec_range[16] 0.020000 - 0.050000 : 6402 [20090617-10:50:38.476887667] msec_range[17] 0.010000 - 0.020000 : 3782 [20090617-10:50:38.480435144] msec_range[18] 0.000000 - 0.010000 : 1661441 [20090617-10:50:38.483198929] [20090617-10:50:38.486144432] [ close] 0.002000 0.005750 0.049000 6537 [20090617-10:50:38.489352442] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-10:50:38.493004125] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-10:50:38.496201214] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-10:50:38.499149416] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-10:50:38.501923031] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-10:50:38.505011794] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-10:50:38.509128301] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-10:50:38.512499599] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-10:50:38.515831252] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-10:50:38.519234076] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-10:50:38.522330365] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-10:50:38.525520547] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-10:50:38.528637987] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-10:50:38.537551866] msec_range[13] 0.200000 - 0.500000 : 0 [20090617-10:50:38.540479942] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-10:50:38.543395845] msec_range[15] 0.050000 - 0.100000 : 0 [20090617-10:50:38.546276398] msec_range[16] 0.020000 - 0.050000 : 7 [20090617-10:50:38.549210101] msec_range[17] 0.010000 - 0.020000 : 413 [20090617-10:50:38.552034099] msec_range[18] 0.000000 - 0.010000 : 6117 [20090617-10:50:38.558639107] [20090617-10:50:38.561548028] [20090617-10:50:38.564224826] [20090617-10:50:38.566980901] [20090617-10:50:38.569662773] 1.1% User Time [20090617-10:50:38.572397889] 44.1% System Time [20090617-10:50:38.575004728] 45.2% CPU Utilization [20090617-10:50:38.577593647] Profilers reporting [20090617-10:50:49.012719763] Profilers postprocessing [20090617-10:50:49.235826367] Processing File : iostat.001 [20090617-10:50:49.238273629] Discovered iostat_interval=[5] [20090617-10:50:49.987672949] Processing Directory : sar.breakout.001 [20090617-10:50:49.989680623] Discovered sar_interval=[5] [20090617-10:50:50.170888990] Processing File : mpstat.001 [20090617-10:50:50.175689846] Discovered mpstat_interval=[5] [20090617-10:50:51.312919658] Stopping profiling. [20090617-10:50:51.317686546] Killing daemon. [20090617-10:50:53.599220889] Processing File : /autobench/logs/ffsb.random_writes__threads_0008.09-06-17_10.32.53/analysis/oprofile.001 [20090617-10:50:53.601594861] Processing File : /autobench/logs/ffsb.random_writes__threads_0008.09-06-17_10.32.53/analysis/oprofile-brief.001 [20090617-10:50:54.650781545] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-06-17_0940/btrfs-newformat-6-17' [20090617-10:50:56.561526503] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090617-10:50:59.805719382] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090617-10:51:00.095851194] PROCESSING COMMAND : 'run random_writes__threads_0032 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb num_threads=32' [20090617-10:51:00.142185143] new log requested [20090617-10:51:00.173297404] Running command ffsb [20090617-10:51:09.103387008] 06/17/2009-10:51:09 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb Succeeded [20090617-10:51:09.114516012] Importing argument : num_threads=32 [20090617-10:51:09.142954261] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090617-10:51:09.219076802] FFSB version 6.0-RC2.1 started [20090617-10:51:09.221317453] [20090617-10:51:09.352594671] benchmark time = 300 [20090617-10:51:09.354746521] ThreadGroup 0 [20090617-10:51:09.356960384] ================ [20090617-10:51:09.359115619] num_threads = 32 [20090617-10:51:09.361405657] [20090617-10:51:09.363366288] read_random = off [20090617-10:51:09.365736500] read_size = 0 (0B) [20090617-10:51:09.367788436] read_blocksize = 0 (0B) [20090617-10:51:09.369761118] read_skip = off [20090617-10:51:09.371648505] read_skipsize = 0 (0B) [20090617-10:51:09.373596712] [20090617-10:51:09.375450194] write_random = on [20090617-10:51:09.377388542] write_size = 1048576 (1MB) [20090617-10:51:09.379188466] fsync_file = 0 [20090617-10:51:09.381115870] write_blocksize = 4096 (4KB) [20090617-10:51:09.382964191] wait time = 0 [20090617-10:51:09.384863537] [20090617-10:51:09.386684599] op weights [20090617-10:51:09.388563789] read = 0 (0.00%) [20090617-10:51:09.390397538] readall = 0 (0.00%) [20090617-10:51:09.392303028] write = 1 (100.00%) [20090617-10:51:09.394318662] create = 0 (0.00%) [20090617-10:51:09.396219263] append = 0 (0.00%) [20090617-10:51:09.398349877] delete = 0 (0.00%) [20090617-10:51:09.400373238] metaop = 0 (0.00%) [20090617-10:51:09.402373605] createdir = 0 (0.00%) [20090617-10:51:09.404246140] stat = 0 (0.00%) [20090617-10:51:09.406176681] writeall = 0 (0.00%) [20090617-10:51:09.408083798] writeall_fsync = 0 (0.00%) [20090617-10:51:09.410015129] open_close = 0 (0.00%) [20090617-10:51:09.411870692] write_fsync = 0 (0.00%) [20090617-10:51:09.413786710] create_fsync = 0 (0.00%) [20090617-10:51:09.415680933] append_fsync = 0 (0.00%) [20090617-10:51:09.417732318] [20090617-10:51:09.419565686] FileSystem /mnt/ffsb1 [20090617-10:51:09.421469743] ========== [20090617-10:51:09.423351066] num_dirs = 0 [20090617-10:51:09.425301333] starting files = 1024 [20090617-10:51:09.427166265] [20090617-10:51:09.429083473] min file size = 36700160 (35MB) [20090617-10:51:09.430965824] max file size = 36700160 (35MB) [20090617-10:51:09.432910196] directio = off [20090617-10:51:09.434758245] alignedio = on [20090617-10:51:09.436639052] bufferedio = off [20090617-10:51:09.438456617] [20090617-10:51:09.440317782] aging is off [20090617-10:51:09.442250872] current utilization = 60.25% [20090617-10:51:09.444221342] [20090617-10:51:09.446098574] creating new fileset /mnt/ffsb1 [20090617-11:04:33.191402990] fs setup took 803 secs [20090617-11:04:40.617799113] Syncing()...7 sec [20090617-11:04:40.620751536] Starting Actual Benchmark At: Wed Jun 17 11:04:40 2009 [20090617-11:04:40.684832401] [20090617-11:11:03.968688751] Syncing()...12 sec [20090617-11:11:04.011424026] FFSB benchmark finished at: Wed Jun 17 11:11:03 2009 [20090617-11:11:04.014511479] [20090617-11:11:04.017481047] Results: [20090617-11:11:04.040277320] Benchmark took 383.20 sec [20090617-11:11:04.043410318] [20090617-11:11:04.045945437] Total Results [20090617-11:11:04.062600865] =============== [20090617-11:11:04.066062619] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090617-11:11:04.069263660] ======= ============ ========= ======= =========== ========== [20090617-11:11:04.072775987] write : 1521664 3970.92 100.000% 100.000% 15.5MB/sec [20090617-11:11:04.076105298] - [20090617-11:11:04.078809427] 3970.92 Transactions per Second [20090617-11:11:04.081386220] [20090617-11:11:04.084013827] Throughput Results [20090617-11:11:04.100521792] =================== [20090617-11:11:04.102996597] Write Throughput: 15.5MB/sec [20090617-11:11:04.105450662] [20090617-11:11:04.108340198] System Call Latency statistics in millisecs [20090617-11:11:04.111584173] ===== [20090617-11:11:04.113949193] Min Avg Max Total Calls [20090617-11:11:04.116973692] ======== ======== ======== ============ [20090617-11:11:04.119772437] [ open] 0.007000 0.588426 246.927002 5944 [20090617-11:11:04.122316080] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-11:11:04.124671644] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-11:11:04.127546672] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-11:11:04.130252688] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-11:11:04.132762848] msec_range[4] 200.000000 - 500.000000 : 8 [20090617-11:11:04.135313509] msec_range[5] 100.000000 - 200.000000 : 8 [20090617-11:11:04.137976331] msec_range[6] 50.000000 - 100.000000 : 1 [20090617-11:11:04.140691332] msec_range[7] 20.000000 - 50.000000 : 1 [20090617-11:11:04.143224127] msec_range[8] 10.000000 - 20.000000 : 3 [20090617-11:11:04.145467214] msec_range[9] 5.000000 - 10.000000 : 2 [20090617-11:11:04.148254970] msec_range[10] 2.000000 - 5.000000 : 4 [20090617-11:11:04.150934637] msec_range[11] 1.000000 - 2.000000 : 1 [20090617-11:11:04.153455421] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-11:11:04.155813506] msec_range[13] 0.200000 - 0.500000 : 11 [20090617-11:11:04.158663544] msec_range[14] 0.100000 - 0.200000 : 215 [20090617-11:11:04.161331791] msec_range[15] 0.050000 - 0.100000 : 851 [20090617-11:11:04.163846964] msec_range[16] 0.020000 - 0.050000 : 1943 [20090617-11:11:04.166666769] msec_range[17] 0.010000 - 0.020000 : 2863 [20090617-11:11:04.169296731] msec_range[18] 0.000000 - 0.010000 : 33 [20090617-11:11:04.172153905] [20090617-11:11:04.174597177] [ write] 0.008000 6.764529 69783.296875 1521664 [20090617-11:11:04.177830824] msec_range[0] 5000.000000 - 10000.000000 : 127 [20090617-11:11:04.181155085] msec_range[1] 2000.000000 - 5000.000000 : 224 [20090617-11:11:04.184306324] msec_range[2] 1000.000000 - 2000.000000 : 152 [20090617-11:11:04.187327924] msec_range[3] 500.000000 - 1000.000000 : 247 [20090617-11:11:04.190092508] msec_range[4] 200.000000 - 500.000000 : 679 [20090617-11:11:04.192909487] msec_range[5] 100.000000 - 200.000000 : 750 [20090617-11:11:04.195321715] msec_range[6] 50.000000 - 100.000000 : 463 [20090617-11:11:04.198240110] msec_range[7] 20.000000 - 50.000000 : 358 [20090617-11:11:04.201048137] msec_range[8] 10.000000 - 20.000000 : 211 [20090617-11:11:04.204834819] msec_range[9] 5.000000 - 10.000000 : 155 [20090617-11:11:04.207880365] msec_range[10] 2.000000 - 5.000000 : 249 [20090617-11:11:04.210989277] msec_range[11] 1.000000 - 2.000000 : 2986 [20090617-11:11:04.252419130] msec_range[12] 0.500000 - 1.000000 : 29246 [20090617-11:11:04.255106612] msec_range[13] 0.200000 - 0.500000 : 96287 [20090617-11:11:04.257983959] msec_range[14] 0.100000 - 0.200000 : 102641 [20090617-11:11:04.260742405] msec_range[15] 0.050000 - 0.100000 : 125128 [20090617-11:11:04.263293100] msec_range[16] 0.020000 - 0.050000 : 527412 [20090617-11:11:04.266144657] msec_range[17] 0.010000 - 0.020000 : 633617 [20090617-11:11:04.268694225] msec_range[18] 0.000000 - 0.010000 : 406 [20090617-11:11:04.271480917] [20090617-11:11:04.274909883] [ lseek] 0.000000 0.932610 65579.445312 1521664 [20090617-11:11:04.278238010] msec_range[0] 5000.000000 - 10000.000000 : 22 [20090617-11:11:04.280886992] msec_range[1] 2000.000000 - 5000.000000 : 42 [20090617-11:11:04.283825279] msec_range[2] 1000.000000 - 2000.000000 : 31 [20090617-11:11:04.286567029] msec_range[3] 500.000000 - 1000.000000 : 33 [20090617-11:11:04.289319815] msec_range[4] 200.000000 - 500.000000 : 48 [20090617-11:11:04.292157963] msec_range[5] 100.000000 - 200.000000 : 35 [20090617-11:11:04.294498998] msec_range[6] 50.000000 - 100.000000 : 20 [20090617-11:11:04.297371748] msec_range[7] 20.000000 - 50.000000 : 26 [20090617-11:11:04.300127121] msec_range[8] 10.000000 - 20.000000 : 7 [20090617-11:11:04.302830740] msec_range[9] 5.000000 - 10.000000 : 4 [20090617-11:11:04.305211727] msec_range[10] 2.000000 - 5.000000 : 11 [20090617-11:11:04.308026667] msec_range[11] 1.000000 - 2.000000 : 12 [20090617-11:11:04.310740394] msec_range[12] 0.500000 - 1.000000 : 117 [20090617-11:11:04.313267210] msec_range[13] 0.200000 - 0.500000 : 1240 [20090617-11:11:04.315586198] msec_range[14] 0.100000 - 0.200000 : 1467 [20090617-11:11:04.318457183] msec_range[15] 0.050000 - 0.100000 : 2151 [20090617-11:11:04.321176389] msec_range[16] 0.020000 - 0.050000 : 10730 [20090617-11:11:04.323826106] msec_range[17] 0.010000 - 0.020000 : 8170 [20090617-11:11:04.326164326] msec_range[18] 0.000000 - 0.010000 : 1497459 [20090617-11:11:04.328964159] [20090617-11:11:04.332355370] [ close] 0.002000 0.021943 88.011002 5944 [20090617-11:11:04.335090998] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-11:11:04.337700119] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-11:11:04.340368370] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-11:11:04.343152962] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-11:11:04.346324440] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-11:11:04.349128333] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-11:11:04.351931681] msec_range[6] 50.000000 - 100.000000 : 1 [20090617-11:11:04.354784824] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-11:11:04.357545361] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-11:11:04.360129168] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-11:11:04.362499838] msec_range[10] 2.000000 - 5.000000 : 2 [20090617-11:11:04.364815185] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-11:11:04.367557860] msec_range[12] 0.500000 - 1.000000 : 1 [20090617-11:11:04.370455689] msec_range[13] 0.200000 - 0.500000 : 1 [20090617-11:11:04.373831251] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-11:11:04.377715850] msec_range[15] 0.050000 - 0.100000 : 1 [20090617-11:11:04.380843483] msec_range[16] 0.020000 - 0.050000 : 39 [20090617-11:11:04.383941671] msec_range[17] 0.010000 - 0.020000 : 556 [20090617-11:11:04.387251352] msec_range[18] 0.000000 - 0.010000 : 5343 [20090617-11:11:04.390336672] [20090617-11:11:04.393196062] [20090617-11:11:04.396143611] [20090617-11:11:04.399365722] [20090617-11:11:04.402344617] 0.9% User Time [20090617-11:11:04.405497584] 63.3% System Time [20090617-11:11:04.408256476] 64.2% CPU Utilization [20090617-11:11:04.411413399] Profilers reporting [20090617-11:11:14.960628105] Profilers postprocessing [20090617-11:11:15.188216921] Processing File : iostat.001 [20090617-11:11:15.190698357] Discovered iostat_interval=[5] [20090617-11:11:16.037363491] Processing Directory : sar.breakout.001 [20090617-11:11:16.039447444] Discovered sar_interval=[5] [20090617-11:11:16.231152868] Processing File : mpstat.001 [20090617-11:11:16.233637046] Discovered mpstat_interval=[5] [20090617-11:11:17.371128770] Stopping profiling. [20090617-11:11:17.377099735] Killing daemon. [20090617-11:11:19.650671247] Processing File : /autobench/logs/ffsb.random_writes__threads_0032.09-06-17_10.51.00/analysis/oprofile.001 [20090617-11:11:19.653268129] Processing File : /autobench/logs/ffsb.random_writes__threads_0032.09-06-17_10.51.00/analysis/oprofile-brief.001 [20090617-11:11:20.801164681] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-06-17_0940/btrfs-newformat-6-17' [20090617-11:11:22.708500039] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090617-11:11:25.883509590] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090617-11:11:26.184610308] PROCESSING COMMAND : 'run random_writes_odirect__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes_odirect.ffsb num_threads=1' [20090617-11:11:26.232115003] new log requested [20090617-11:11:26.268859090] Running command ffsb [20090617-11:11:35.188371287] 06/17/2009-11:11:35 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes_odirect.ffsb Succeeded [20090617-11:11:35.199656431] Importing argument : num_threads=1 [20090617-11:11:35.227872521] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090617-11:11:35.306974252] FFSB version 6.0-RC2.1 started [20090617-11:11:35.309238518] [20090617-11:11:35.311496628] benchmark time = 300 [20090617-11:11:35.313738578] ThreadGroup 0 [20090617-11:11:35.315789765] ================ [20090617-11:11:35.318024548] num_threads = 1 [20090617-11:11:35.320133855] [20090617-11:11:35.322408695] read_random = off [20090617-11:11:35.324426785] read_size = 0 (0B) [20090617-11:11:35.326440877] read_blocksize = 0 (0B) [20090617-11:11:35.328345208] read_skip = off [20090617-11:11:35.330303515] read_skipsize = 0 (0B) [20090617-11:11:35.332225598] [20090617-11:11:35.334178006] write_random = on [20090617-11:11:35.336048836] write_size = 1048576 (1MB) [20090617-11:11:35.337996302] fsync_file = 0 [20090617-11:11:35.339940801] write_blocksize = 4096 (4KB) [20090617-11:11:35.341849565] wait time = 0 [20090617-11:11:35.343890142] [20090617-11:11:35.345981041] op weights [20090617-11:11:35.348095278] read = 0 (0.00%) [20090617-11:11:35.349987435] readall = 0 (0.00%) [20090617-11:11:35.351964450] write = 1 (100.00%) [20090617-11:11:35.353960766] create = 0 (0.00%) [20090617-11:11:35.355968171] append = 0 (0.00%) [20090617-11:11:35.357848250] delete = 0 (0.00%) [20090617-11:11:35.359853461] metaop = 0 (0.00%) [20090617-11:11:35.361946634] createdir = 0 (0.00%) [20090617-11:11:35.363919495] stat = 0 (0.00%) [20090617-11:11:35.365809980] writeall = 0 (0.00%) [20090617-11:11:35.367787177] writeall_fsync = 0 (0.00%) [20090617-11:11:35.369868779] open_close = 0 (0.00%) [20090617-11:11:35.372041900] write_fsync = 0 (0.00%) [20090617-11:11:35.373912945] create_fsync = 0 (0.00%) [20090617-11:11:35.375853593] append_fsync = 0 (0.00%) [20090617-11:11:35.377778167] [20090617-11:11:35.379994201] FileSystem /mnt/ffsb1 [20090617-11:11:35.381846482] ========== [20090617-11:11:35.383788520] num_dirs = 0 [20090617-11:11:35.385684133] starting files = 1024 [20090617-11:11:35.387680185] [20090617-11:11:35.389520643] min file size = 36700160 (35MB) [20090617-11:11:35.391460412] max file size = 36700160 (35MB) [20090617-11:11:35.393506270] directio = on [20090617-11:11:35.395457551] alignedio = on [20090617-11:11:35.397304024] bufferedio = off [20090617-11:11:35.399252407] [20090617-11:11:35.401554416] aging is off [20090617-11:11:35.403522229] current utilization = 59.54% [20090617-11:11:35.405381955] [20090617-11:11:35.407338376] creating new fileset /mnt/ffsb1 [20090617-11:24:42.863243916] fs setup took 787 secs [20090617-11:24:50.485578176] Syncing()...7 sec [20090617-11:24:50.488330675] Starting Actual Benchmark At: Wed Jun 17 11:24:50 2009 [20090617-11:24:50.528870099] [20090617-11:29:52.267805151] Syncing()...0 sec [20090617-11:29:52.271317645] FFSB benchmark finished at: Wed Jun 17 11:29:52 2009 [20090617-11:29:52.274449886] [20090617-11:29:52.277597638] Results: [20090617-11:29:52.295685816] Benchmark took 301.78 sec [20090617-11:29:52.298498177] [20090617-11:29:52.301448324] Total Results [20090617-11:29:52.318798419] =============== [20090617-11:29:52.322066887] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090617-11:29:52.325082089] ======= ============ ========= ======= =========== ========== [20090617-11:29:52.327951639] write : 73984 245.16 100.000% 100.000% 981KB/sec [20090617-11:29:52.330874747] - [20090617-11:29:52.333543950] 245.16 Transactions per Second [20090617-11:29:52.336251781] [20090617-11:29:52.339157832] Throughput Results [20090617-11:29:52.355794651] =================== [20090617-11:29:52.358787794] Write Throughput: 981KB/sec [20090617-11:29:52.361572813] [20090617-11:29:52.364657331] System Call Latency statistics in millisecs [20090617-11:29:52.368113361] ===== [20090617-11:29:52.371038657] Min Avg Max Total Calls [20090617-11:29:52.374022777] ======== ======== ======== ============ [20090617-11:29:52.376831612] [ open] 0.007000 0.093972 5.643000 289 [20090617-11:29:52.379849271] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-11:29:52.383093878] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-11:29:52.386352404] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-11:29:52.389587064] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-11:29:52.392750287] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-11:29:52.396512057] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-11:29:52.400875048] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-11:29:52.403712556] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-11:29:52.406971339] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-11:29:52.410986708] msec_range[9] 5.000000 - 10.000000 : 1 [20090617-11:29:52.414310776] msec_range[10] 2.000000 - 5.000000 : 4 [20090617-11:29:52.417354789] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-11:29:52.424303997] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-11:29:52.427477158] msec_range[13] 0.200000 - 0.500000 : 3 [20090617-11:29:52.430332849] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-11:29:52.434596417] msec_range[15] 0.050000 - 0.100000 : 18 [20090617-11:29:52.437615536] msec_range[16] 0.020000 - 0.050000 : 48 [20090617-11:29:52.440612130] msec_range[17] 0.010000 - 0.020000 : 61 [20090617-11:29:52.443699163] msec_range[18] 0.000000 - 0.010000 : 154 [20090617-11:29:52.447184099] [20090617-11:29:52.449629961] [ write] 0.474000 4.067340 213.766006 73984 [20090617-11:29:52.452770928] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-11:29:52.455850341] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-11:29:52.459017275] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-11:29:52.461852915] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-11:29:52.464706951] msec_range[4] 200.000000 - 500.000000 : 1 [20090617-11:29:52.467772122] msec_range[5] 100.000000 - 200.000000 : 6 [20090617-11:29:52.470714929] msec_range[6] 50.000000 - 100.000000 : 3 [20090617-11:29:52.473704318] msec_range[7] 20.000000 - 50.000000 : 11 [20090617-11:29:52.477172363] msec_range[8] 10.000000 - 20.000000 : 63 [20090617-11:29:52.480226211] msec_range[9] 5.000000 - 10.000000 : 236 [20090617-11:29:52.483162831] msec_range[10] 2.000000 - 5.000000 : 73368 [20090617-11:29:52.486222663] msec_range[11] 1.000000 - 2.000000 : 249 [20090617-11:29:52.489171593] msec_range[12] 0.500000 - 1.000000 : 46 [20090617-11:29:52.492287409] msec_range[13] 0.200000 - 0.500000 : 1 [20090617-11:29:52.495349730] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-11:29:52.498573950] msec_range[15] 0.050000 - 0.100000 : 0 [20090617-11:29:52.501558250] msec_range[16] 0.020000 - 0.050000 : 0 [20090617-11:29:52.505404426] msec_range[17] 0.010000 - 0.020000 : 0 [20090617-11:29:52.508325144] msec_range[18] 0.000000 - 0.010000 : 0 [20090617-11:29:52.511469007] [20090617-11:29:52.518773855] [ lseek] 0.000000 0.001432 0.021000 73984 [20090617-11:29:52.523093336] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-11:29:52.526310540] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-11:29:52.538429090] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-11:29:52.541427257] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-11:29:52.544426393] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-11:29:52.547678516] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-11:29:52.553346904] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-11:29:52.556656270] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-11:29:52.559955235] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-11:29:52.563006500] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-11:29:52.567817025] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-11:29:52.572372359] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-11:29:52.575494832] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-11:29:52.578724806] msec_range[13] 0.200000 - 0.500000 : 0 [20090617-11:29:52.583250390] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-11:29:52.586630697] msec_range[15] 0.050000 - 0.100000 : 0 [20090617-11:29:52.589854422] msec_range[16] 0.020000 - 0.050000 : 1 [20090617-11:29:52.592696366] msec_range[17] 0.010000 - 0.020000 : 6 [20090617-11:29:52.595557002] msec_range[18] 0.000000 - 0.010000 : 73977 [20090617-11:29:52.598517851] [20090617-11:29:52.601395394] [ close] 0.003000 0.003782 0.011000 289 [20090617-11:29:52.604364733] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-11:29:52.607216985] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-11:29:52.610108603] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-11:29:52.613203208] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-11:29:52.616266291] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-11:29:52.620083974] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-11:29:52.623196346] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-11:29:52.626031096] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-11:29:52.629087707] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-11:29:52.632137142] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-11:29:52.635024673] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-11:29:52.637728216] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-11:29:52.640790474] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-11:29:52.644055812] msec_range[13] 0.200000 - 0.500000 : 0 [20090617-11:29:52.647170692] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-11:29:52.650018538] msec_range[15] 0.050000 - 0.100000 : 0 [20090617-11:29:52.653131032] msec_range[16] 0.020000 - 0.050000 : 0 [20090617-11:29:52.656093895] msec_range[17] 0.010000 - 0.020000 : 2 [20090617-11:29:52.659330974] msec_range[18] 0.000000 - 0.010000 : 287 [20090617-11:29:52.662379950] [20090617-11:29:52.665126441] [20090617-11:29:52.668083312] [20090617-11:29:52.671151565] [20090617-11:29:52.674239536] 0.1% User Time [20090617-11:29:52.677281901] 1.6% System Time [20090617-11:29:52.680372588] 1.7% CPU Utilization [20090617-11:29:52.683318149] Profilers reporting [20090617-11:30:01.892415999] Profilers postprocessing [20090617-11:30:02.131808407] Processing File : iostat.001 [20090617-11:30:02.134217451] Discovered iostat_interval=[5] [20090617-11:30:02.861999214] Processing Directory : sar.breakout.001 [20090617-11:30:02.864340594] Discovered sar_interval=[5] [20090617-11:30:03.029440305] Processing File : mpstat.001 [20090617-11:30:03.031765431] Discovered mpstat_interval=[5] [20090617-11:30:04.171619362] Stopping profiling. [20090617-11:30:04.178706876] Killing daemon. [20090617-11:30:05.409999125] Processing File : /autobench/logs/ffsb.random_writes_odirect__threads_0001.09-06-17_11.11.26/analysis/oprofile.001 [20090617-11:30:05.412405681] Processing File : /autobench/logs/ffsb.random_writes_odirect__threads_0001.09-06-17_11.11.26/analysis/oprofile-brief.001 [20090617-11:30:06.419697907] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-06-17_0940/btrfs-newformat-6-17' [20090617-11:30:08.159098584] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090617-11:30:10.488004220] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090617-11:30:10.719821993] PROCESSING COMMAND : 'run random_writes_odirect__threads_0008 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes_odirect.ffsb num_threads=8' [20090617-11:30:10.766245837] new log requested [20090617-11:30:10.796606787] Running command ffsb [20090617-11:30:19.626774908] 06/17/2009-11:30:19 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes_odirect.ffsb Succeeded [20090617-11:30:19.637684920] Importing argument : num_threads=8 [20090617-11:30:19.665245891] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090617-11:30:19.743434306] FFSB version 6.0-RC2.1 started [20090617-11:30:19.745680356] [20090617-11:30:19.776745282] benchmark time = 300 [20090617-11:30:19.778630544] ThreadGroup 0 [20090617-11:30:19.780801642] ================ [20090617-11:30:19.782882134] num_threads = 8 [20090617-11:30:19.784753996] [20090617-11:30:19.786903266] read_random = off [20090617-11:30:19.789064982] read_size = 0 (0B) [20090617-11:30:19.791218998] read_blocksize = 0 (0B) [20090617-11:30:19.793150998] read_skip = off [20090617-11:30:19.795147482] read_skipsize = 0 (0B) [20090617-11:30:19.797066980] [20090617-11:30:19.799374357] write_random = on [20090617-11:30:19.801275475] write_size = 1048576 (1MB) [20090617-11:30:19.803220967] fsync_file = 0 [20090617-11:30:19.805116664] write_blocksize = 4096 (4KB) [20090617-11:30:19.807331596] wait time = 0 [20090617-11:30:19.809220448] [20090617-11:30:19.811163081] op weights [20090617-11:30:19.813050793] read = 0 (0.00%) [20090617-11:30:19.815164185] readall = 0 (0.00%) [20090617-11:30:19.817090806] write = 1 (100.00%) [20090617-11:30:19.819074815] create = 0 (0.00%) [20090617-11:30:19.820923857] append = 0 (0.00%) [20090617-11:30:19.823197820] delete = 0 (0.00%) [20090617-11:30:19.825055863] metaop = 0 (0.00%) [20090617-11:30:19.827047884] createdir = 0 (0.00%) [20090617-11:30:19.828906070] stat = 0 (0.00%) [20090617-11:30:19.830898237] writeall = 0 (0.00%) [20090617-11:30:19.832831223] writeall_fsync = 0 (0.00%) [20090617-11:30:19.834794113] open_close = 0 (0.00%) [20090617-11:30:19.836908977] write_fsync = 0 (0.00%) [20090617-11:30:19.838933340] create_fsync = 0 (0.00%) [20090617-11:30:19.840788254] append_fsync = 0 (0.00%) [20090617-11:30:19.842711767] [20090617-11:30:19.844642557] FileSystem /mnt/ffsb1 [20090617-11:30:19.847029035] ========== [20090617-11:30:19.848968825] num_dirs = 0 [20090617-11:30:19.850947943] starting files = 1024 [20090617-11:30:19.852849906] [20090617-11:30:19.854816500] min file size = 36700160 (35MB) [20090617-11:30:19.856704702] max file size = 36700160 (35MB) [20090617-11:30:19.858649906] directio = on [20090617-11:30:19.860527735] alignedio = on [20090617-11:30:19.862529530] bufferedio = off [20090617-11:30:19.864411855] [20090617-11:30:19.866378272] aging is off [20090617-11:30:19.868252384] current utilization = 51.70% [20090617-11:30:19.870200837] [20090617-11:30:19.872062038] creating new fileset /mnt/ffsb1 [20090617-11:37:01.578899405] fs setup took 401 secs [20090617-11:37:09.053663569] Syncing()...7 sec [20090617-11:37:09.056352394] Starting Actual Benchmark At: Wed Jun 17 11:37:09 2009 [20090617-11:37:09.146667660] [20090617-11:42:12.571763272] Syncing()...1 sec [20090617-11:42:12.575332884] FFSB benchmark finished at: Wed Jun 17 11:42:12 2009 [20090617-11:42:12.578768259] [20090617-11:42:12.582039258] Results: [20090617-11:42:12.599010121] Benchmark took 303.52 sec [20090617-11:42:12.602072163] [20090617-11:42:12.605031775] Total Results [20090617-11:42:12.622049888] =============== [20090617-11:42:12.624879490] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090617-11:42:12.627703575] ======= ============ ========= ======= =========== ========== [20090617-11:42:12.630809648] write : 497664 1639.65 100.000% 100.000% 6.4MB/sec [20090617-11:42:12.633555080] - [20090617-11:42:12.636377790] 1639.65 Transactions per Second [20090617-11:42:12.639754154] [20090617-11:42:12.642708735] Throughput Results [20090617-11:42:12.660591135] =================== [20090617-11:42:12.664561404] Write Throughput: 6.4MB/sec [20090617-11:42:12.667794103] [20090617-11:42:12.671093536] System Call Latency statistics in millisecs [20090617-11:42:12.674318270] ===== [20090617-11:42:12.678325047] Min Avg Max Total Calls [20090617-11:42:12.681388626] ======== ======== ======== ============ [20090617-11:42:12.684688195] [ open] 0.007000 0.016865 0.207000 1944 [20090617-11:42:12.688573054] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-11:42:12.692020255] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-11:42:12.695544388] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-11:42:12.698621977] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-11:42:12.701650115] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-11:42:12.705122763] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-11:42:12.708402574] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-11:42:12.711631408] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-11:42:12.715588832] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-11:42:12.720300438] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-11:42:12.723606972] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-11:42:12.727750910] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-11:42:12.731831895] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-11:42:12.734972785] msec_range[13] 0.200000 - 0.500000 : 1 [20090617-11:42:12.738383252] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-11:42:12.741663082] msec_range[15] 0.050000 - 0.100000 : 52 [20090617-11:42:12.744920857] msec_range[16] 0.020000 - 0.050000 : 458 [20090617-11:42:12.748386450] msec_range[17] 0.010000 - 0.020000 : 1041 [20090617-11:42:12.753897650] msec_range[18] 0.000000 - 0.010000 : 392 [20090617-11:42:12.756841826] [20090617-11:42:12.759620387] [ write] 0.705000 4.841781 1741.342041 497664 [20090617-11:42:12.764396469] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-11:42:12.767471831] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-11:42:12.770136487] msec_range[2] 1000.000000 - 2000.000000 : 48 [20090617-11:42:12.772660238] msec_range[3] 500.000000 - 1000.000000 : 17 [20090617-11:42:12.775533342] msec_range[4] 200.000000 - 500.000000 : 17 [20090617-11:42:12.778343407] msec_range[5] 100.000000 - 200.000000 : 40 [20090617-11:42:12.780934972] msec_range[6] 50.000000 - 100.000000 : 574 [20090617-11:42:12.783488747] msec_range[7] 20.000000 - 50.000000 : 3414 [20090617-11:42:12.785969611] msec_range[8] 10.000000 - 20.000000 : 4849 [20090617-11:42:12.788460042] msec_range[9] 5.000000 - 10.000000 : 10283 [20090617-11:42:12.791209473] msec_range[10] 2.000000 - 5.000000 : 471375 [20090617-11:42:12.794236431] msec_range[11] 1.000000 - 2.000000 : 6881 [20090617-11:42:12.797520114] msec_range[12] 0.500000 - 1.000000 : 166 [20090617-11:42:12.802611057] msec_range[13] 0.200000 - 0.500000 : 0 [20090617-11:42:12.814925667] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-11:42:12.818734314] msec_range[15] 0.050000 - 0.100000 : 0 [20090617-11:42:12.822633542] msec_range[16] 0.020000 - 0.050000 : 0 [20090617-11:42:12.828699303] msec_range[17] 0.010000 - 0.020000 : 0 [20090617-11:42:12.832126352] msec_range[18] 0.000000 - 0.010000 : 0 [20090617-11:42:12.835405330] [20090617-11:42:12.840869464] [ lseek] 0.000000 0.001597 0.203000 497664 [20090617-11:42:12.844614079] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-11:42:12.848113913] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-11:42:12.851197297] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-11:42:12.854489354] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-11:42:12.857569688] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-11:42:12.860463242] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-11:42:12.863556374] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-11:42:12.867135366] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-11:42:12.870482630] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-11:42:12.873799832] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-11:42:12.878033779] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-11:42:12.883077382] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-11:42:12.885893587] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-11:42:12.888636416] msec_range[13] 0.200000 - 0.500000 : 1 [20090617-11:42:12.891810612] msec_range[14] 0.100000 - 0.200000 : 3 [20090617-11:42:12.895003370] msec_range[15] 0.050000 - 0.100000 : 0 [20090617-11:42:12.898338848] msec_range[16] 0.020000 - 0.050000 : 127 [20090617-11:42:12.901168576] msec_range[17] 0.010000 - 0.020000 : 582 [20090617-11:42:12.904065793] msec_range[18] 0.000000 - 0.010000 : 496951 [20090617-11:42:12.907329903] [20090617-11:42:12.910368792] [ close] 0.002000 0.004971 0.028000 1944 [20090617-11:42:12.913494285] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-11:42:12.916745925] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-11:42:12.920356858] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-11:42:12.923644413] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-11:42:12.926613677] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-11:42:12.929422817] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-11:42:12.932668667] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-11:42:12.935785138] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-11:42:12.938575846] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-11:42:12.941718565] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-11:42:12.944819794] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-11:42:12.948155184] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-11:42:12.951374540] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-11:42:12.954601255] msec_range[13] 0.200000 - 0.500000 : 0 [20090617-11:42:12.959965847] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-11:42:12.962972288] msec_range[15] 0.050000 - 0.100000 : 0 [20090617-11:42:12.965880950] msec_range[16] 0.020000 - 0.050000 : 7 [20090617-11:42:12.968838250] msec_range[17] 0.010000 - 0.020000 : 85 [20090617-11:42:12.972298820] msec_range[18] 0.000000 - 0.010000 : 1852 [20090617-11:42:12.975323512] [20090617-11:42:12.978154586] [20090617-11:42:12.981019690] [20090617-11:42:12.984209681] [20090617-11:42:12.987062707] 0.5% User Time [20090617-11:42:12.990063858] 13.1% System Time [20090617-11:42:12.993157670] 13.6% CPU Utilization [20090617-11:42:12.996041089] Profilers reporting [20090617-11:42:22.164104028] Profilers postprocessing [20090617-11:42:22.382112630] Processing File : iostat.001 [20090617-11:42:22.384533758] Discovered iostat_interval=[5] [20090617-11:42:23.128678275] Processing Directory : sar.breakout.001 [20090617-11:42:23.131175785] Discovered sar_interval=[5] [20090617-11:42:23.296830223] Processing File : mpstat.001 [20090617-11:42:23.299198390] Discovered mpstat_interval=[5] [20090617-11:42:24.440741109] Stopping profiling. [20090617-11:42:24.444694558] Killing daemon. [20090617-11:42:25.674186687] Processing File : /autobench/logs/ffsb.random_writes_odirect__threads_0008.09-06-17_11.30.10/analysis/oprofile.001 [20090617-11:42:25.677645043] Processing File : /autobench/logs/ffsb.random_writes_odirect__threads_0008.09-06-17_11.30.10/analysis/oprofile-brief.001 [20090617-11:42:26.715195340] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-06-17_0940/btrfs-newformat-6-17' [20090617-11:42:28.517982931] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090617-11:42:30.941288996] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090617-11:42:31.193833424] PROCESSING COMMAND : 'run random_writes_odirect__threads_0032 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes_odirect.ffsb num_threads=32' [20090617-11:42:31.240203231] new log requested [20090617-11:42:31.270592454] Running command ffsb [20090617-11:42:40.126943454] 06/17/2009-11:42:40 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes_odirect.ffsb Succeeded [20090617-11:42:40.138127255] Importing argument : num_threads=32 [20090617-11:42:40.166483038] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090617-11:42:40.243010959] FFSB version 6.0-RC2.1 started [20090617-11:42:40.245396167] [20090617-11:42:40.376392568] benchmark time = 300 [20090617-11:42:40.378637000] ThreadGroup 0 [20090617-11:42:40.380982956] ================ [20090617-11:42:40.383203858] num_threads = 32 [20090617-11:42:40.385602354] [20090617-11:42:40.387792459] read_random = off [20090617-11:42:40.389903682] read_size = 0 (0B) [20090617-11:42:40.391831098] read_blocksize = 0 (0B) [20090617-11:42:40.393844485] read_skip = off [20090617-11:42:40.395874214] read_skipsize = 0 (0B) [20090617-11:42:40.397936787] [20090617-11:42:40.399966444] write_random = on [20090617-11:42:40.401903690] write_size = 1048576 (1MB) [20090617-11:42:40.404019995] fsync_file = 0 [20090617-11:42:40.405960997] write_blocksize = 4096 (4KB) [20090617-11:42:40.407986839] wait time = 0 [20090617-11:42:40.409889907] [20090617-11:42:40.411881665] op weights [20090617-11:42:40.413823571] read = 0 (0.00%) [20090617-11:42:40.415840315] readall = 0 (0.00%) [20090617-11:42:40.417720364] write = 1 (100.00%) [20090617-11:42:40.419670239] create = 0 (0.00%) [20090617-11:42:40.421563202] append = 0 (0.00%) [20090617-11:42:40.423544393] delete = 0 (0.00%) [20090617-11:42:40.425427351] metaop = 0 (0.00%) [20090617-11:42:40.427382414] createdir = 0 (0.00%) [20090617-11:42:40.429260554] stat = 0 (0.00%) [20090617-11:42:40.431233815] writeall = 0 (0.00%) [20090617-11:42:40.433210866] writeall_fsync = 0 (0.00%) [20090617-11:42:40.435140327] open_close = 0 (0.00%) [20090617-11:42:40.437174027] write_fsync = 0 (0.00%) [20090617-11:42:40.439066013] create_fsync = 0 (0.00%) [20090617-11:42:40.440999189] append_fsync = 0 (0.00%) [20090617-11:42:40.442885714] [20090617-11:42:40.444876969] FileSystem /mnt/ffsb1 [20090617-11:42:40.446780864] ========== [20090617-11:42:40.448728069] num_dirs = 0 [20090617-11:42:40.450589109] starting files = 1024 [20090617-11:42:40.452585803] [20090617-11:42:40.454456267] min file size = 36700160 (35MB) [20090617-11:42:40.456335507] max file size = 36700160 (35MB) [20090617-11:42:40.458231464] directio = on [20090617-11:42:40.460197747] alignedio = on [20090617-11:42:40.462096305] bufferedio = off [20090617-11:42:40.464076915] [20090617-11:42:40.465925166] aging is off [20090617-11:42:40.467863065] current utilization = 54.10% [20090617-11:42:40.469722268] [20090617-11:42:40.471698420] creating new fileset /mnt/ffsb1 [20090617-11:50:53.486401919] fs setup took 492 secs [20090617-11:51:00.961458096] Syncing()...7 sec [20090617-11:51:00.963974838] Starting Actual Benchmark At: Wed Jun 17 11:51:00 2009 [20090617-11:51:01.006650801] [20090617-11:56:09.455766946] Syncing()...1 sec [20090617-11:56:09.459126285] FFSB benchmark finished at: Wed Jun 17 11:56:09 2009 [20090617-11:56:09.462445408] [20090617-11:56:09.466424868] Results: [20090617-11:56:09.483167299] Benchmark took 308.49 sec [20090617-11:56:09.486045741] [20090617-11:56:09.488958004] Total Results [20090617-11:56:09.505958925] =============== [20090617-11:56:09.509381961] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090617-11:56:09.513043551] ======= ============ ========= ======= =========== ========== [20090617-11:56:09.516418550] write : 1071872 3474.53 100.000% 100.000% 13.6MB/sec [20090617-11:56:09.519226683] - [20090617-11:56:09.522294973] 3474.53 Transactions per Second [20090617-11:56:09.525317729] [20090617-11:56:09.528233175] Throughput Results [20090617-11:56:09.551348212] =================== [20090617-11:56:09.553899690] Write Throughput: 13.6MB/sec [20090617-11:56:09.556695894] [20090617-11:56:09.559340702] System Call Latency statistics in millisecs [20090617-11:56:09.561983166] ===== [20090617-11:56:09.564880895] Min Avg Max Total Calls [20090617-11:56:09.569521209] ======== ======== ======== ============ [20090617-11:56:09.574057948] [ open] 0.006000 0.068856 36.027000 4187 [20090617-11:56:09.577207759] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-11:56:09.580298811] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-11:56:09.583517574] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-11:56:09.586610172] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-11:56:09.590506757] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-11:56:09.594815795] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-11:56:09.598111556] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-11:56:09.601960118] msec_range[7] 20.000000 - 50.000000 : 8 [20090617-11:56:09.606819382] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-11:56:09.609771113] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-11:56:09.612798503] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-11:56:09.617580445] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-11:56:09.620873928] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-11:56:09.623938942] msec_range[13] 0.200000 - 0.500000 : 4 [20090617-11:56:09.627120167] msec_range[14] 0.100000 - 0.200000 : 13 [20090617-11:56:09.630486156] msec_range[15] 0.050000 - 0.100000 : 133 [20090617-11:56:09.633712946] msec_range[16] 0.020000 - 0.050000 : 998 [20090617-11:56:09.637255871] msec_range[17] 0.010000 - 0.020000 : 2194 [20090617-11:56:09.640562207] msec_range[18] 0.000000 - 0.010000 : 837 [20090617-11:56:09.643673047] [20090617-11:56:09.647521675] [ write] 1.182000 9.083663 3034.697021 1071872 [20090617-11:56:09.650664763] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-11:56:09.655210290] msec_range[1] 2000.000000 - 5000.000000 : 371 [20090617-11:56:09.658517234] msec_range[2] 1000.000000 - 2000.000000 : 137 [20090617-11:56:09.662160898] msec_range[3] 500.000000 - 1000.000000 : 311 [20090617-11:56:09.665778288] msec_range[4] 200.000000 - 500.000000 : 2307 [20090617-11:56:09.668905805] msec_range[5] 100.000000 - 200.000000 : 5355 [20090617-11:56:09.672155312] msec_range[6] 50.000000 - 100.000000 : 9409 [20090617-11:56:09.676676639] msec_range[7] 20.000000 - 50.000000 : 18133 [20090617-11:56:09.679828922] msec_range[8] 10.000000 - 20.000000 : 19335 [20090617-11:56:09.682824444] msec_range[9] 5.000000 - 10.000000 : 749183 [20090617-11:56:09.685663162] msec_range[10] 2.000000 - 5.000000 : 267125 [20090617-11:56:09.688639547] msec_range[11] 1.000000 - 2.000000 : 206 [20090617-11:56:09.692373900] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-11:56:09.695377814] msec_range[13] 0.200000 - 0.500000 : 0 [20090617-11:56:09.698468038] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-11:56:09.701520455] msec_range[15] 0.050000 - 0.100000 : 0 [20090617-11:56:09.704614825] msec_range[16] 0.020000 - 0.050000 : 0 [20090617-11:56:09.709094427] msec_range[17] 0.010000 - 0.020000 : 0 [20090617-11:56:09.712710195] msec_range[18] 0.000000 - 0.010000 : 0 [20090617-11:56:09.715735049] [20090617-11:56:09.719525724] [ lseek] 0.000000 0.001698 0.394000 1071872 [20090617-11:56:09.722655713] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-11:56:09.725868752] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-11:56:09.728887785] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-11:56:09.732313911] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-11:56:09.738169489] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-11:56:09.741084185] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-11:56:09.744052941] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-11:56:09.746981995] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-11:56:09.750085437] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-11:56:09.753548778] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-11:56:09.758140994] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-11:56:09.761316528] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-11:56:09.764417959] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-11:56:09.767392566] msec_range[13] 0.200000 - 0.500000 : 3 [20090617-11:56:09.773110666] msec_range[14] 0.100000 - 0.200000 : 2 [20090617-11:56:09.776300459] msec_range[15] 0.050000 - 0.100000 : 17 [20090617-11:56:09.780780276] msec_range[16] 0.020000 - 0.050000 : 360 [20090617-11:56:09.784046322] msec_range[17] 0.010000 - 0.020000 : 1989 [20090617-11:56:09.787342438] msec_range[18] 0.000000 - 0.010000 : 1069501 [20090617-11:56:09.790194505] [20090617-11:56:09.793405359] [ close] 0.002000 0.005231 0.201000 4187 [20090617-11:56:09.796631436] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-11:56:09.799997173] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-11:56:09.803163400] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-11:56:09.806572378] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-11:56:09.809441869] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-11:56:09.812529528] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-11:56:09.815325403] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-11:56:09.818445433] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-11:56:09.821467151] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-11:56:09.824232247] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-11:56:09.827519157] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-11:56:09.830665581] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-11:56:09.833342022] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-11:56:09.836306288] msec_range[13] 0.200000 - 0.500000 : 1 [20090617-11:56:09.839160032] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-11:56:09.842282420] msec_range[15] 0.050000 - 0.100000 : 1 [20090617-11:56:09.845255828] msec_range[16] 0.020000 - 0.050000 : 16 [20090617-11:56:09.848149481] msec_range[17] 0.010000 - 0.020000 : 203 [20090617-11:56:09.850917130] msec_range[18] 0.000000 - 0.010000 : 3966 [20090617-11:56:09.853678188] [20090617-11:56:09.856943380] [20090617-11:56:09.860002669] [20090617-11:56:09.862683100] [20090617-11:56:09.865582175] 1.0% User Time [20090617-11:56:09.868479158] 28.7% System Time [20090617-11:56:09.871433380] 29.7% CPU Utilization [20090617-11:56:09.874325333] Profilers reporting [20090617-11:56:19.281222239] Profilers postprocessing [20090617-11:56:19.510685178] Processing File : iostat.001 [20090617-11:56:19.513117633] Discovered iostat_interval=[5] [20090617-11:56:20.272529122] Processing Directory : sar.breakout.001 [20090617-11:56:20.274819976] Discovered sar_interval=[5] [20090617-11:56:20.442559402] Processing File : mpstat.001 [20090617-11:56:20.445028555] Discovered mpstat_interval=[5] [20090617-11:56:21.591673451] Stopping profiling. [20090617-11:56:21.597611997] Killing daemon. [20090617-11:56:22.830737684] Processing File : /autobench/logs/ffsb.random_writes_odirect__threads_0032.09-06-17_11.42.31/analysis/oprofile.001 [20090617-11:56:22.833419953] Processing File : /autobench/logs/ffsb.random_writes_odirect__threads_0032.09-06-17_11.42.31/analysis/oprofile-brief.001 [20090617-11:56:23.967258976] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-06-17_0940/btrfs-newformat-6-17' [20090617-11:56:25.867752618] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090617-11:56:28.518286373] PROCESSING COMMAND : 'mkfs.btrfs /dev/ffsbdev1' [20090617-11:56:28.567012588] [20090617-11:56:28.569379518] WARNING! - Btrfs v0.18-13-gb8420fa IS EXPERIMENTAL [20090617-11:56:28.571555615] WARNING! - see http://btrfs.wiki.kernel.org before using [20090617-11:56:28.573956028] [20090617-11:56:28.575927552] fs created label (null) on /dev/ffsbdev1 [20090617-11:56:28.577842666] nodesize 4096 leafsize 4096 sectorsize 4096 size 68.37GB [20090617-11:56:28.579715986] Btrfs v0.18-13-gb8420fa [20090617-11:56:28.707032501] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090617-11:56:28.806931251] PROCESSING COMMAND : 'run large_file_creates__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/large_file_creates.ffsb num_threads=1' [20090617-11:56:28.853203203] new log requested [20090617-11:56:28.883382808] Running command ffsb [20090617-11:56:37.683188775] 06/17/2009-11:56:37 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/large_file_creates.ffsb Succeeded [20090617-11:56:37.694442638] Importing argument : num_threads=1 [20090617-11:56:37.723144810] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090617-11:56:37.804259160] FFSB version 6.0-RC2.1 started [20090617-11:56:37.806363621] [20090617-11:56:37.808624308] benchmark time = 300 [20090617-11:56:37.810705136] ThreadGroup 0 [20090617-11:56:37.813035940] ================ [20090617-11:56:37.815104750] num_threads = 1 [20090617-11:56:37.817313505] [20090617-11:56:37.819478306] read_random = off [20090617-11:56:37.821829932] read_size = 0 (0B) [20090617-11:56:37.824023533] read_blocksize = 0 (0B) [20090617-11:56:37.826041970] read_skip = off [20090617-11:56:37.827909804] read_skipsize = 0 (0B) [20090617-11:56:37.830062287] [20090617-11:56:37.832038479] write_random = off [20090617-11:56:37.833968676] write_size = 0 (0B) [20090617-11:56:37.835795007] fsync_file = 0 [20090617-11:56:37.837728555] write_blocksize = 4096 (4KB) [20090617-11:56:37.839592900] wait time = 0 [20090617-11:56:37.841504793] [20090617-11:56:37.843338791] op weights [20090617-11:56:37.845267664] read = 0 (0.00%) [20090617-11:56:37.847132608] readall = 0 (0.00%) [20090617-11:56:37.849038390] write = 0 (0.00%) [20090617-11:56:37.850868766] create = 1 (100.00%) [20090617-11:56:37.852784514] append = 0 (0.00%) [20090617-11:56:37.854570213] delete = 0 (0.00%) [20090617-11:56:37.856493511] metaop = 0 (0.00%) [20090617-11:56:37.858317542] createdir = 0 (0.00%) [20090617-11:56:37.860219425] stat = 0 (0.00%) [20090617-11:56:37.862052022] writeall = 0 (0.00%) [20090617-11:56:37.863954054] writeall_fsync = 0 (0.00%) [20090617-11:56:37.865783712] open_close = 0 (0.00%) [20090617-11:56:37.867723969] write_fsync = 0 (0.00%) [20090617-11:56:37.869583422] create_fsync = 0 (0.00%) [20090617-11:56:37.871496043] append_fsync = 0 (0.00%) [20090617-11:56:37.873313022] [20090617-11:56:37.875225707] FileSystem /mnt/ffsb1 [20090617-11:56:37.877064008] ========== [20090617-11:56:37.878964704] num_dirs = 0 [20090617-11:56:37.880768422] starting files = 0 [20090617-11:56:37.882669109] [20090617-11:56:37.884517043] min file size = 104857600 (100MB) [20090617-11:56:37.886445095] max file size = 104857600 (100MB) [20090617-11:56:37.888278528] directio = off [20090617-11:56:37.890195785] alignedio = on [20090617-11:56:37.892034214] bufferedio = off [20090617-11:56:37.893973461] [20090617-11:56:37.895780977] aging is off [20090617-11:56:37.897683321] current utilization = 0.00% [20090617-11:56:37.899523948] [20090617-11:56:37.901426407] creating new fileset /mnt/ffsb1 [20090617-11:56:37.903270180] fs setup took 0 secs [20090617-11:56:38.837100966] Syncing()...1 sec [20090617-11:56:38.839112293] Starting Actual Benchmark At: Wed Jun 17 11:56:38 2009 [20090617-11:56:38.852807549] [20090617-12:01:48.637314316] Syncing()...7 sec [20090617-12:01:48.675030515] FFSB benchmark finished at: Wed Jun 17 12:01:48 2009 [20090617-12:01:48.678405046] [20090617-12:01:48.681697530] Results: [20090617-12:01:48.705280354] Benchmark took 309.59 sec [20090617-12:01:48.707947498] [20090617-12:01:48.710408151] Total Results [20090617-12:01:48.728507571] =============== [20090617-12:01:48.731269328] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090617-12:01:48.734499711] ======= ============ ========= ======= =========== ========== [20090617-12:01:48.737267576] create : 7398400 23897.41 100.000% 100.000% 93.3MB/sec [20090617-12:01:48.740071817] - [20090617-12:01:48.742925444] 23897.41 Transactions per Second [20090617-12:01:48.746003353] [20090617-12:01:48.748852584] Throughput Results [20090617-12:01:48.764940090] =================== [20090617-12:01:48.767916934] Write Throughput: 93.3MB/sec [20090617-12:01:48.770614188] [20090617-12:01:48.776855357] System Call Latency statistics in millisecs [20090617-12:01:48.779366518] ===== [20090617-12:01:48.781935987] Min Avg Max Total Calls [20090617-12:01:48.784437821] ======== ======== ======== ============ [20090617-12:01:48.786952177] [ open] 0.064000 0.127370 0.679000 289 [20090617-12:01:48.789711861] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-12:01:48.792681270] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-12:01:48.795457274] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-12:01:48.798083378] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-12:01:48.800685426] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-12:01:48.803007341] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-12:01:48.805615944] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-12:01:48.808165993] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-12:01:48.810540755] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-12:01:48.812764886] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-12:01:48.815420692] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-12:01:48.818081489] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-12:01:48.820428591] msec_range[12] 0.500000 - 1.000000 : 3 [20090617-12:01:48.822684750] msec_range[13] 0.200000 - 0.500000 : 18 [20090617-12:01:48.825406726] msec_range[14] 0.100000 - 0.200000 : 199 [20090617-12:01:48.828346595] msec_range[15] 0.050000 - 0.100000 : 69 [20090617-12:01:48.831305944] msec_range[16] 0.020000 - 0.050000 : 0 [20090617-12:01:48.834311200] msec_range[17] 0.010000 - 0.020000 : 0 [20090617-12:01:48.837243463] msec_range[18] 0.000000 - 0.010000 : 0 [20090617-12:01:48.840258676] [20090617-12:01:48.843183409] [ write] 0.012000 0.040332 3414.686035 7398400 [20090617-12:01:48.846105212] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-12:01:48.850104906] msec_range[1] 2000.000000 - 5000.000000 : 1 [20090617-12:01:48.853244317] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-12:01:48.856029240] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-12:01:48.859560063] msec_range[4] 200.000000 - 500.000000 : 11 [20090617-12:01:48.863161946] msec_range[5] 100.000000 - 200.000000 : 818 [20090617-12:01:48.866169520] msec_range[6] 50.000000 - 100.000000 : 224 [20090617-12:01:48.869010967] msec_range[7] 20.000000 - 50.000000 : 16 [20090617-12:01:48.871876065] msec_range[8] 10.000000 - 20.000000 : 69 [20090617-12:01:48.875364807] msec_range[9] 5.000000 - 10.000000 : 4132 [20090617-12:01:48.878069414] msec_range[10] 2.000000 - 5.000000 : 114 [20090617-12:01:48.880675544] msec_range[11] 1.000000 - 2.000000 : 4 [20090617-12:01:48.883662628] msec_range[12] 0.500000 - 1.000000 : 7 [20090617-12:01:48.886705599] msec_range[13] 0.200000 - 0.500000 : 1584 [20090617-12:01:48.890658470] msec_range[14] 0.100000 - 0.200000 : 104 [20090617-12:01:48.893392540] msec_range[15] 0.050000 - 0.100000 : 2015 [20090617-12:01:48.896855802] msec_range[16] 0.020000 - 0.050000 : 4334237 [20090617-12:01:48.899888990] msec_range[17] 0.010000 - 0.020000 : 3055064 [20090617-12:01:48.902724499] msec_range[18] 0.000000 - 0.010000 : 0 [20090617-12:01:48.905353732] [20090617-12:01:48.907957789] [ close] 0.006000 0.008270 0.017000 289 [20090617-12:01:48.910467643] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-12:01:48.912994330] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-12:01:48.915945220] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-12:01:48.919925216] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-12:01:48.923012042] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-12:01:48.926287010] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-12:01:48.929432956] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-12:01:48.932428435] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-12:01:48.935768717] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-12:01:48.938767044] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-12:01:48.941742517] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-12:01:48.944565840] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-12:01:48.947322314] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-12:01:48.949647678] msec_range[13] 0.200000 - 0.500000 : 0 [20090617-12:01:48.952392504] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-12:01:48.955352453] msec_range[15] 0.050000 - 0.100000 : 0 [20090617-12:01:48.958424372] msec_range[16] 0.020000 - 0.050000 : 0 [20090617-12:01:48.961434296] msec_range[17] 0.010000 - 0.020000 : 59 [20090617-12:01:48.964119873] msec_range[18] 0.000000 - 0.010000 : 230 [20090617-12:01:48.966718265] [20090617-12:01:48.969612712] [20090617-12:01:48.972134441] [20090617-12:01:48.974952639] [20090617-12:01:48.977798303] 2.9% User Time [20090617-12:01:48.981322409] 59.0% System Time [20090617-12:01:48.984146674] 61.9% CPU Utilization [20090617-12:01:48.987070879] Profilers reporting [20090617-12:02:00.135623102] Profilers postprocessing [20090617-12:02:00.296980906] Processing File : iostat.001 [20090617-12:02:00.299155599] Discovered iostat_interval=[5] [20090617-12:02:01.053397365] Processing Directory : sar.breakout.001 [20090617-12:02:01.055733846] Discovered sar_interval=[5] [20090617-12:02:01.248947153] Processing File : mpstat.001 [20090617-12:02:01.251273078] Discovered mpstat_interval=[5] [20090617-12:02:02.389899455] Stopping profiling. [20090617-12:02:02.396566646] Killing daemon. [20090617-12:02:04.657403658] Processing File : /autobench/logs/ffsb.large_file_creates__threads_0001.09-06-17_11.56.28/analysis/oprofile.001 [20090617-12:02:04.659724823] Processing File : /autobench/logs/ffsb.large_file_creates__threads_0001.09-06-17_11.56.28/analysis/oprofile-brief.001 [20090617-12:02:05.511524046] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-06-17_0940/btrfs-newformat-6-17' [20090617-12:02:07.393910834] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090617-12:02:09.621544795] PROCESSING COMMAND : 'mkfs.btrfs /dev/ffsbdev1' [20090617-12:02:09.674846570] [20090617-12:02:09.677259610] WARNING! - Btrfs v0.18-13-gb8420fa IS EXPERIMENTAL [20090617-12:02:09.679545525] WARNING! - see http://btrfs.wiki.kernel.org before using [20090617-12:02:09.681950568] [20090617-12:02:09.683901861] fs created label (null) on /dev/ffsbdev1 [20090617-12:02:09.685838748] nodesize 4096 leafsize 4096 sectorsize 4096 size 68.37GB [20090617-12:02:09.687693494] Btrfs v0.18-13-gb8420fa [20090617-12:02:09.819271988] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090617-12:02:09.921042821] PROCESSING COMMAND : 'run large_file_creates__threads_0008 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/large_file_creates.ffsb num_threads=8' [20090617-12:02:09.967019783] new log requested [20090617-12:02:09.997097261] Running command ffsb [20090617-12:02:18.597997021] 06/17/2009-12:02:18 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs2/large_file_creates.ffsb Succeeded [20090617-12:02:18.607798288] Importing argument : num_threads=8 [20090617-12:02:18.635497030] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090617-12:02:18.724845337] FFSB version 6.0-RC2.1 started [20090617-12:02:18.726883901] [20090617-12:02:18.755479528] benchmark time = 300 [20090617-12:02:18.757287323] ThreadGroup 0 [20090617-12:02:18.759504906] ================ [20090617-12:02:18.761706880] num_threads = 8 [20090617-12:02:18.763780767] [20090617-12:02:18.765943040] read_random = off [20090617-12:02:18.768176982] read_size = 0 (0B) [20090617-12:02:18.770318962] read_blocksize = 0 (0B) [20090617-12:02:18.772445511] read_skip = off [20090617-12:02:18.774354082] read_skipsize = 0 (0B) [20090617-12:02:18.776406404] [20090617-12:02:18.778268355] write_random = off [20090617-12:02:18.780219293] write_size = 0 (0B) [20090617-12:02:18.782092525] fsync_file = 0 [20090617-12:02:18.784060068] write_blocksize = 4096 (4KB) [20090617-12:02:18.785888936] wait time = 0 [20090617-12:02:18.787829778] [20090617-12:02:18.789693330] op weights [20090617-12:02:18.791641226] read = 0 (0.00%) [20090617-12:02:18.793479693] readall = 0 (0.00%) [20090617-12:02:18.795393622] write = 0 (0.00%) [20090617-12:02:18.797231307] create = 1 (100.00%) [20090617-12:02:18.799169021] append = 0 (0.00%) [20090617-12:02:18.800955167] delete = 0 (0.00%) [20090617-12:02:18.802865912] metaop = 0 (0.00%) [20090617-12:02:18.804705744] createdir = 0 (0.00%) [20090617-12:02:18.806628499] stat = 0 (0.00%) [20090617-12:02:18.808467391] writeall = 0 (0.00%) [20090617-12:02:18.810383901] writeall_fsync = 0 (0.00%) [20090617-12:02:18.812172513] open_close = 0 (0.00%) [20090617-12:02:18.814127161] write_fsync = 0 (0.00%) [20090617-12:02:18.815914606] create_fsync = 0 (0.00%) [20090617-12:02:18.817825861] append_fsync = 0 (0.00%) [20090617-12:02:18.819675559] [20090617-12:02:18.821664272] FileSystem /mnt/ffsb1 [20090617-12:02:18.823766495] ========== [20090617-12:02:18.825732808] num_dirs = 0 [20090617-12:02:18.828006624] starting files = 0 [20090617-12:02:18.830027386] [20090617-12:02:18.831967683] min file size = 104857600 (100MB) [20090617-12:02:18.833834028] max file size = 104857600 (100MB) [20090617-12:02:18.835836136] directio = off [20090617-12:02:18.837726742] alignedio = on [20090617-12:02:18.839658635] bufferedio = off [20090617-12:02:18.841507476] [20090617-12:02:18.843451086] aging is off [20090617-12:02:18.845326991] current utilization = 0.00% [20090617-12:02:18.847243458] [20090617-12:02:18.849098769] creating new fileset /mnt/ffsb1 [20090617-12:02:18.851068216] fs setup took 0 secs [20090617-12:02:19.891097814] Syncing()...1 sec [20090617-12:02:19.893069566] Starting Actual Benchmark At: Wed Jun 17 12:02:19 2009 [20090617-12:02:19.907505357] [20090617-12:07:38.988698215] Syncing()...10 sec [20090617-12:07:39.055729008] FFSB benchmark finished at: Wed Jun 17 12:07:38 2009 [20090617-12:07:39.058763684] [20090617-12:07:39.062001180] Results: [20090617-12:07:39.082979081] Benchmark took 318.77 sec [20090617-12:07:39.086134721] [20090617-12:07:39.088653252] Total Results [20090617-12:07:39.105145241] =============== [20090617-12:07:39.107611999] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090617-12:07:39.110174476] ======= ============ ========= ======= =========== ========== [20090617-12:07:39.112873695] create : 6553600 20559.07 100.000% 100.000% 80.3MB/sec [20090617-12:07:39.116862786] - [20090617-12:07:39.119927595] 20559.07 Transactions per Second [20090617-12:07:39.122705794] [20090617-12:07:39.125447245] Throughput Results [20090617-12:07:39.143241910] =================== [20090617-12:07:39.146452177] Write Throughput: 80.3MB/sec [20090617-12:07:39.149301351] [20090617-12:07:39.152192621] System Call Latency statistics in millisecs [20090617-12:07:39.155129075] ===== [20090617-12:07:39.158403577] Min Avg Max Total Calls [20090617-12:07:39.160980398] ======== ======== ======== ============ [20090617-12:07:39.164227394] [ open] 0.112000 0.313512 0.713000 256 [20090617-12:07:39.166971693] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-12:07:39.169775425] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-12:07:39.172227856] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-12:07:39.181107828] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-12:07:39.183525723] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-12:07:39.186174165] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-12:07:39.189101103] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-12:07:39.191804097] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-12:07:39.194680097] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-12:07:39.197114038] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-12:07:39.199684159] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-12:07:39.202589871] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-12:07:39.205103782] msec_range[12] 0.500000 - 1.000000 : 5 [20090617-12:07:39.207638276] msec_range[13] 0.200000 - 0.500000 : 232 [20090617-12:07:39.211376457] msec_range[14] 0.100000 - 0.200000 : 19 [20090617-12:07:39.214169412] msec_range[15] 0.050000 - 0.100000 : 0 [20090617-12:07:39.216743554] msec_range[16] 0.020000 - 0.050000 : 0 [20090617-12:07:39.219782915] msec_range[17] 0.010000 - 0.020000 : 0 [20090617-12:07:39.222571545] msec_range[18] 0.000000 - 0.010000 : 0 [20090617-12:07:39.225258984] [20090617-12:07:39.227763186] [ write] 0.011000 0.375349 891.757996 6553600 [20090617-12:07:39.230140472] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-12:07:39.232797311] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-12:07:39.235528627] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-12:07:39.238102088] msec_range[3] 500.000000 - 1000.000000 : 84 [20090617-12:07:39.240656636] msec_range[4] 200.000000 - 500.000000 : 6007 [20090617-12:07:39.243321429] msec_range[5] 100.000000 - 200.000000 : 2681 [20090617-12:07:39.246413032] msec_range[6] 50.000000 - 100.000000 : 289 [20090617-12:07:39.248920177] msec_range[7] 20.000000 - 50.000000 : 126 [20090617-12:07:39.251249075] msec_range[8] 10.000000 - 20.000000 : 122 [20090617-12:07:39.253867029] msec_range[9] 5.000000 - 10.000000 : 55 [20090617-12:07:39.256706919] msec_range[10] 2.000000 - 5.000000 : 311 [20090617-12:07:39.259052071] msec_range[11] 1.000000 - 2.000000 : 100 [20090617-12:07:39.261345854] msec_range[12] 0.500000 - 1.000000 : 1025 [20090617-12:07:39.264094208] msec_range[13] 0.200000 - 0.500000 : 60609 [20090617-12:07:39.266855791] msec_range[14] 0.100000 - 0.200000 : 545974 [20090617-12:07:39.269529616] msec_range[15] 0.050000 - 0.100000 : 3903960 [20090617-12:07:39.272230413] msec_range[16] 0.020000 - 0.050000 : 1985322 [20090617-12:07:39.274798300] msec_range[17] 0.010000 - 0.020000 : 46935 [20090617-12:07:39.277290100] msec_range[18] 0.000000 - 0.010000 : 0 [20090617-12:07:39.279617212] [20090617-12:07:39.282239349] [ close] 0.004000 0.009363 0.018000 256 [20090617-12:07:39.284821812] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090617-12:07:39.287302992] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090617-12:07:39.289559747] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090617-12:07:39.292219259] msec_range[3] 500.000000 - 1000.000000 : 0 [20090617-12:07:39.294789912] msec_range[4] 200.000000 - 500.000000 : 0 [20090617-12:07:39.297225204] msec_range[5] 100.000000 - 200.000000 : 0 [20090617-12:07:39.299474918] msec_range[6] 50.000000 - 100.000000 : 0 [20090617-12:07:39.302050153] msec_range[7] 20.000000 - 50.000000 : 0 [20090617-12:07:39.304528262] msec_range[8] 10.000000 - 20.000000 : 0 [20090617-12:07:39.307245208] msec_range[9] 5.000000 - 10.000000 : 0 [20090617-12:07:39.309970997] msec_range[10] 2.000000 - 5.000000 : 0 [20090617-12:07:39.312599441] msec_range[11] 1.000000 - 2.000000 : 0 [20090617-12:07:39.315249455] msec_range[12] 0.500000 - 1.000000 : 0 [20090617-12:07:39.318369658] msec_range[13] 0.200000 - 0.500000 : 0 [20090617-12:07:39.321254312] msec_range[14] 0.100000 - 0.200000 : 0 [20090617-12:07:39.323969159] msec_range[15] 0.050000 - 0.100000 : 0 [20090617-12:07:39.326729198] msec_range[16] 0.020000 - 0.050000 : 0 [20090617-12:07:39.329358379] msec_range[17] 0.010000 - 0.020000 : 85 [20090617-12:07:39.332671340] msec_range[18] 0.000000 - 0.010000 : 171 [20090617-12:07:39.335759979] [20090617-12:07:39.338976996] [20090617-12:07:39.342135642] [20090617-12:07:39.344977498] [20090617-12:07:39.347689494] 2.9% User Time [20090617-12:07:39.350286710] 154.9% System Time [20090617-12:07:39.352823844] 157.8% CPU Utilization [20090617-12:07:39.355385901] Profilers reporting [20090617-12:07:49.753975956] Profilers postprocessing [20090617-12:07:49.972340803] Processing File : iostat.001 [20090617-12:07:49.974785509] Discovered iostat_interval=[5] [20090617-12:07:50.748803310] Processing Directory : sar.breakout.001 [20090617-12:07:50.750801218] Discovered sar_interval=[5] [20090617-12:07:50.931896831] Processing File : mpstat.001 [20090617-12:07:50.934083275] Discovered mpstat_interval=[5] [20090617-12:07:52.074914569] Stopping profiling. [20090617-12:07:52.081854818] Killing daemon. [20090617-12:07:54.343362034] Processing File : /autobench/logs/ffsb.large_file_creates__threads_0008.09-06-17_12.02.09/analysis/oprofile.001 [20090617-12:07:54.345744186] Processing File : /autobench/logs/ffsb.large_file_creates__threads_0008.09-06-17_12.02.09/analysis/oprofile-brief.001 [20090617-12:07:55.484432394] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2009-06-17_0940/btrfs-newformat-6-17'