[20081217-09:00:13.146083016] PROCESSING COMMAND : 'clearprofilers' [20081217-09:00:13.412662820] PROCESSING COMMAND : 'useprofiler iostat 5' [20081217-09:00:13.519335020] Checking for sar... [20081217-09:00:13.521965398] found [20081217-09:00:13.663457701] PROCESSING COMMAND : 'useprofiler sar 5' [20081217-09:00:13.770728712] Checking for sar... [20081217-09:00:13.773530928] found [20081217-09:00:13.915647517] PROCESSING COMMAND : 'useprofiler mpstat 5' [20081217-09:00:14.021971408] Checking for sar... [20081217-09:00:14.024104424] found [20081217-09:00:14.197065500] PROCESSING COMMAND : 'useprofiler oprofile' [20081217-09:00:14.410269777] Checking for binutils-2.18 ... [20081217-09:00:14.421156539] Already installed. [20081217-09:00:14.476167436] Checking for oprofile-0.9.4-autobench ... [20081217-09:00:14.486990503] Already installed. [20081217-09:00:14.537964595] opcontrol: oprofile 0.9.4 compiled on Nov 19 2008 09:09:21 [20081217-09:00:14.617496934] Daemon not running [20081217-09:00:14.640814757] Unloading oprofile module [20081217-09:00:14.900942792] Daemon not running [20081217-09:00:15.770871385] OPROFILE : using callgraph [5] [20081217-09:00:16.002527266] Daemon not running [20081217-09:00:16.004643532] Separate options: none [20081217-09:00:16.006789156] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-09:00:16.008582730] Image filter: none [20081217-09:00:16.010578619] Call-graph depth: 5 [20081217-09:00:16.217066484] PROCESSING COMMAND : 'umount /mnt/ffsb1 > /dev/null 2>&1' [20081217-09:00:16.291448784] PROCESSING COMMAND : 'set-sched noop' [20081217-09:00:16.671106241] PROCESSING COMMAND : 'mkresultdirs hks.austin.ibm.com benchmarks/results/btrfs/ffsb btrfs2 2008-12-17_0900 btrfs-baseline' [20081217-09:00:16.920860428] Connecting to hks.austin.ibm.com... [20081217-09:00:16.923139665] Remote working directory: /opt [20081217-09:00:16.925455533] Remote working directory: /opt/benchmarks/results/btrfs/ffsb [20081217-09:00:16.927733920] Couldn't create directory: Failure [20081217-09:00:16.929875877] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs2 [20081217-09:00:16.932049277] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs2 [20081217-09:00:16.933904167] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-17_0900 [20081217-09:00:16.935787984] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-17_0900 [20081217-09:00:16.937684849] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-17_0900/btrfs-baseline [20081217-09:00:17.006431302] PROCESSING COMMAND : 'mkfs.btrfs -V 2>&1' [20081217-09:00:17.039821769] mkfs.btrfs: invalid option -- V [20081217-09:00:17.042268224] usage: mkfs.btrfs [options] dev [ dev ... ] [20081217-09:00:17.044423736] options: [20081217-09:00:17.046513878] -b --byte-count total number of bytes in the FS [20081217-09:00:17.048337690] -l --leafsize size of btree leaves [20081217-09:00:17.050170107] -n --nodesize size of btree leaves [20081217-09:00:17.051977257] -s --sectorsize min block allocation [20081217-09:00:17.054088607] Btrfs v0.16-28-gb238b4b [20081217-09:00:17.134515624] PROCESSING COMMAND : 'mkfs.btrfs /dev/ffsbdev1' [20081217-09:00:17.175809618] fs created label (null) on /dev/ffsbdev1 [20081217-09:00:17.179255790] nodesize 4096 leafsize 4096 sectorsize 4096 size 68.37GB [20081217-09:00:17.181344702] Btrfs v0.16-28-gb238b4b [20081217-09:00:17.407133728] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-09:00:17.502595004] PROCESSING COMMAND : 'run sequential_reads__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb num_threads=1' [20081217-09:00:17.546728514] new log requested [20081217-09:00:17.569634722] Running command ffsb [20081217-09:00:25.823088015] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb [20081217-09:00:25.836215847] Importing argument : num_threads=1 [20081217-09:00:25.862654326] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-09:00:25.935350395] FFSB version 6.0-RC2 started [20081217-09:00:25.937608877] [20081217-09:00:25.939621644] benchmark time = 300 [20081217-09:00:25.941838341] ThreadGroup 0 [20081217-09:00:25.943889592] ================ [20081217-09:00:25.945888370] num_threads = 1 [20081217-09:00:25.948087450] [20081217-09:00:25.950019888] read_random = off [20081217-09:00:25.951890246] read_size = 0 (0B) [20081217-09:00:25.953688088] read_blocksize = 4096 (4KB) [20081217-09:00:25.955618617] read_skip = off [20081217-09:00:25.957510261] read_skipsize = 0 (0B) [20081217-09:00:25.959299920] [20081217-09:00:25.961195065] write_random = off [20081217-09:00:25.963023427] write_size = 0 (0B) [20081217-09:00:25.964886155] fsync_file = 0 [20081217-09:00:25.966705515] write_blocksize = 0 (0B) [20081217-09:00:25.968631883] wait time = 0 [20081217-09:00:25.970545501] [20081217-09:00:25.972341240] op weights [20081217-09:00:25.974242356] read = 0 (0.00%) [20081217-09:00:25.976063529] readall = 1 (100.00%) [20081217-09:00:25.977958778] write = 0 (0.00%) [20081217-09:00:25.979844186] create = 0 (0.00%) [20081217-09:00:25.981627758] append = 0 (0.00%) [20081217-09:00:25.983461659] delete = 0 (0.00%) [20081217-09:00:25.985262024] metaop = 0 (0.00%) [20081217-09:00:25.987133844] createdir = 0 (0.00%) [20081217-09:00:25.989044981] stat = 0 (0.00%) [20081217-09:00:25.990837212] writeall = 0 (0.00%) [20081217-09:00:25.992717993] writeall_fsync = 0 (0.00%) [20081217-09:00:25.994523266] open_close = 0 (0.00%) [20081217-09:00:25.996369512] write_fsync = 0 (0.00%) [20081217-09:00:25.998147889] create_fsync = 0 (0.00%) [20081217-09:00:26.000059939] append_fsync = 0 (0.00%) [20081217-09:00:26.002003231] [20081217-09:00:26.003786944] FileSystem /mnt/ffsb1 [20081217-09:00:26.005667535] ========== [20081217-09:00:26.007463909] num_dirs = 0 [20081217-09:00:26.009311539] starting files = 1024 [20081217-09:00:26.011103123] [20081217-09:00:26.013015453] min file size = 36700160 (35MB) [20081217-09:00:26.014916386] max file size = 36700160 (35MB) [20081217-09:00:26.016698453] directio = off [20081217-09:00:26.018598333] alignedio = on [20081217-09:00:26.020407397] bufferedio = off [20081217-09:00:26.022255266] [20081217-09:00:26.023994488] aging is off [20081217-09:00:26.025904989] current utilization = 0.00% [20081217-09:00:26.027801501] [20081217-09:00:26.029597315] checking existing fs: /mnt/ffsb1 [20081217-09:00:26.031471023] opendir: No such file or directory [20081217-09:00:26.033269079] recreating new fileset [20081217-09:07:12.943176011] fs setup took 406 secs [20081217-09:07:14.953176899] Syncing()...2 sec [20081217-09:07:14.955560397] Starting Actual Benchmark At: Wed Dec 17 09:07:14 2008 [20081217-09:07:15.006342843] [20081217-09:12:16.275541215] Syncing()...1 sec [20081217-09:12:16.321426586] FFSB benchmark finished at: Wed Dec 17 09:12:16 2008 [20081217-09:12:16.324217030] [20081217-09:12:16.326969652] Results: [20081217-09:12:16.356705925] Benchmark took 301.13 sec [20081217-09:12:16.358793131] [20081217-09:12:16.361386606] Total Results [20081217-09:12:16.376288901] =============== [20081217-09:12:16.378484297] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-09:12:16.381334537] ======= ============ ========= ======= =========== ========== [20081217-09:12:16.384078185] readall : 6755840 22435.31 100.000% 100.000% 87.6MB/sec [20081217-09:12:16.386371144] - [20081217-09:12:16.388603870] 22435.31 Transactions per Second [20081217-09:12:16.390932474] [20081217-09:12:16.393061545] Throughput Results [20081217-09:12:16.408482401] =================== [20081217-09:12:16.410904460] Read Throughput: 87.6MB/sec [20081217-09:12:16.413629253] [20081217-09:12:16.451745573] System Call Latency statistics in millisecs [20081217-09:12:16.454825171] ===== [20081217-09:12:16.457327986] Min Avg Max Total Calls [20081217-09:12:16.459939896] ======== ======== ======== ============ [20081217-09:12:16.462306926] [ open] 0.019000 0.506846 24.073999 754 [20081217-09:12:16.464674075] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:12:16.466938896] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:12:16.469316085] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:12:16.471553556] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-09:12:16.473895501] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-09:12:16.476094657] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-09:12:16.478379570] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-09:12:16.480561960] msec_range[7] 20.000000 - 50.000000 : 3 [20081217-09:12:16.483209574] msec_range[8] 10.000000 - 20.000000 : 9 [20081217-09:12:16.485486559] msec_range[9] 5.000000 - 10.000000 : 18 [20081217-09:12:16.487843151] msec_range[10] 2.000000 - 5.000000 : 8 [20081217-09:12:16.490028838] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-09:12:16.492286104] msec_range[12] 0.500000 - 1.000000 : 1 [20081217-09:12:16.494421594] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-09:12:16.496772730] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-09:12:16.499211538] msec_range[15] 0.050000 - 0.100000 : 38 [20081217-09:12:16.501447480] msec_range[16] 0.020000 - 0.050000 : 676 [20081217-09:12:16.503862684] msec_range[17] 0.010000 - 0.020000 : 1 [20081217-09:12:16.506115698] msec_range[18] 0.000000 - 0.010000 : 0 [20081217-09:12:16.508385569] [20081217-09:12:16.511582685] [ read] 0.004000 0.044046 145.604004 6755840 [20081217-09:12:16.514907969] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:12:16.517428766] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:12:16.520306377] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:12:16.523243131] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-09:12:16.525872417] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-09:12:16.528469144] msec_range[5] 100.000000 - 200.000000 : 20 [20081217-09:12:16.530916527] msec_range[6] 50.000000 - 100.000000 : 410 [20081217-09:12:16.533416957] msec_range[7] 20.000000 - 50.000000 : 603 [20081217-09:12:16.535737922] msec_range[8] 10.000000 - 20.000000 : 676 [20081217-09:12:16.537929563] msec_range[9] 5.000000 - 10.000000 : 7208 [20081217-09:12:16.540450426] msec_range[10] 2.000000 - 5.000000 : 36579 [20081217-09:12:16.542916859] msec_range[11] 1.000000 - 2.000000 : 870 [20081217-09:12:16.545561577] msec_range[12] 0.500000 - 1.000000 : 161 [20081217-09:12:16.548648385] msec_range[13] 0.200000 - 0.500000 : 103 [20081217-09:12:16.550919893] msec_range[14] 0.100000 - 0.200000 : 132 [20081217-09:12:16.553229180] msec_range[15] 0.050000 - 0.100000 : 1222 [20081217-09:12:16.555723491] msec_range[16] 0.020000 - 0.050000 : 1439 [20081217-09:12:16.558094501] msec_range[17] 0.010000 - 0.020000 : 88794 [20081217-09:12:16.560604136] msec_range[18] 0.000000 - 0.010000 : 6617623 [20081217-09:12:16.563027042] [20081217-09:12:16.565461151] [ close] 0.005000 0.006546 0.016000 754 [20081217-09:12:16.567737965] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:12:16.569893994] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:12:16.572192286] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:12:16.574501306] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-09:12:16.576730248] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-09:12:16.578934278] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-09:12:16.581191635] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-09:12:16.583334858] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-09:12:16.585587784] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-09:12:16.587840264] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-09:12:16.590081322] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-09:12:16.592318082] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-09:12:16.594696569] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-09:12:16.597205496] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-09:12:16.599505248] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-09:12:16.601878701] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-09:12:16.604339116] msec_range[16] 0.020000 - 0.050000 : 0 [20081217-09:12:16.606518148] msec_range[17] 0.010000 - 0.020000 : 8 [20081217-09:12:16.608699144] msec_range[18] 0.000000 - 0.010000 : 746 [20081217-09:12:16.610821704] [20081217-09:12:16.613002781] [20081217-09:12:16.615111961] [20081217-09:12:16.617279024] [20081217-09:12:16.619401980] 1.2% User Time [20081217-09:12:16.621534469] 21.9% System Time [20081217-09:12:16.623609473] 23.1% CPU Utilization [20081217-09:12:16.625767150] Profilers reporting [20081217-09:12:16.873301020] /autobench/scripts/doprofilers: line 33: 2956 Terminated ${CMDS[$i]} [20081217-09:12:31.702946342] Profilers postprocessing [20081217-09:12:31.988732502] Processing File : iostat.001 [20081217-09:12:31.990996327] Discovered iostat_interval=[5] [20081217-09:12:32.557717780] Processing Directory : sar.breakout.001 [20081217-09:12:32.560047815] Discovered sar_interval=[5] [20081217-09:12:32.724591829] Processing File : mpstat.001 [20081217-09:12:32.726761662] Discovered mpstat_interval=[5] [20081217-09:12:33.859965053] Stopping profiling. [20081217-09:12:33.864945164] Killing daemon. [20081217-09:12:36.363606568] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0001.08-12-17_09.00.17/analysis/oprofile.001 [20081217-09:12:36.365833583] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0001.08-12-17_09.00.17/analysis/oprofile-brief.001 [20081217-09:12:38.120319585] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-17_0900/btrfs-baseline' [20081217-09:12:40.132570422] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-09:12:41.772822160] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-09:12:41.986129435] PROCESSING COMMAND : 'run sequential_reads__threads_0008 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb num_threads=8' [20081217-09:12:42.028569231] new log requested [20081217-09:12:42.051199888] Running command ffsb [20081217-09:12:50.159350647] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb [20081217-09:12:50.172539278] Importing argument : num_threads=8 [20081217-09:12:50.197960614] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-09:12:50.277587974] FFSB version 6.0-RC2 started [20081217-09:12:50.279755255] [20081217-09:12:50.305958540] benchmark time = 300 [20081217-09:12:50.308047224] ThreadGroup 0 [20081217-09:12:50.310124126] ================ [20081217-09:12:50.312205619] num_threads = 8 [20081217-09:12:50.314130994] [20081217-09:12:50.315896491] read_random = off [20081217-09:12:50.317696747] read_size = 0 (0B) [20081217-09:12:50.319457562] read_blocksize = 4096 (4KB) [20081217-09:12:50.321228488] read_skip = off [20081217-09:12:50.323009046] read_skipsize = 0 (0B) [20081217-09:12:50.324802641] [20081217-09:12:50.326533517] write_random = off [20081217-09:12:50.328326504] write_size = 0 (0B) [20081217-09:12:50.330074967] fsync_file = 0 [20081217-09:12:50.331880675] write_blocksize = 0 (0B) [20081217-09:12:50.333634191] wait time = 0 [20081217-09:12:50.335429826] [20081217-09:12:50.337200181] op weights [20081217-09:12:50.338993559] read = 0 (0.00%) [20081217-09:12:50.340717154] readall = 1 (100.00%) [20081217-09:12:50.342496336] write = 0 (0.00%) [20081217-09:12:50.344192150] create = 0 (0.00%) [20081217-09:12:50.346011017] append = 0 (0.00%) [20081217-09:12:50.347729795] delete = 0 (0.00%) [20081217-09:12:50.349515132] metaop = 0 (0.00%) [20081217-09:12:50.351255566] createdir = 0 (0.00%) [20081217-09:12:50.353107301] stat = 0 (0.00%) [20081217-09:12:50.354862090] writeall = 0 (0.00%) [20081217-09:12:50.356693959] writeall_fsync = 0 (0.00%) [20081217-09:12:50.358423747] open_close = 0 (0.00%) [20081217-09:12:50.360219080] write_fsync = 0 (0.00%) [20081217-09:12:50.362132253] create_fsync = 0 (0.00%) [20081217-09:12:50.364097086] append_fsync = 0 (0.00%) [20081217-09:12:50.365874593] [20081217-09:12:50.367900868] FileSystem /mnt/ffsb1 [20081217-09:12:50.369740305] ========== [20081217-09:12:50.371536673] num_dirs = 0 [20081217-09:12:50.373290536] starting files = 1024 [20081217-09:12:50.375149275] [20081217-09:12:50.376894212] min file size = 36700160 (35MB) [20081217-09:12:50.378712664] max file size = 36700160 (35MB) [20081217-09:12:50.380463171] directio = off [20081217-09:12:50.382256709] alignedio = on [20081217-09:12:50.384025424] bufferedio = off [20081217-09:12:50.385824315] [20081217-09:12:50.387536077] aging is off [20081217-09:12:50.389364840] current utilization = 51.26% [20081217-09:12:50.391103958] [20081217-09:12:50.392892238] checking existing fs: /mnt/ffsb1 [20081217-09:12:50.979136679] fs setup took 0 secs [20081217-09:12:51.420217965] Syncing()...0 sec [20081217-09:12:51.422352614] Starting Actual Benchmark At: Wed Dec 17 09:12:51 2008 [20081217-09:12:51.435476674] [20081217-09:17:55.342461752] Syncing()...0 sec [20081217-09:17:55.400659849] FFSB benchmark finished at: Wed Dec 17 09:17:55 2008 [20081217-09:17:55.403476375] [20081217-09:17:55.406214205] Results: [20081217-09:17:55.492739756] Benchmark took 303.66 sec [20081217-09:17:55.495370704] [20081217-09:17:55.498115778] Total Results [20081217-09:17:55.513265071] =============== [20081217-09:17:55.515559091] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-09:17:55.517869320] ======= ============ ========= ======= =========== ========== [20081217-09:17:55.520246044] readall : 6406400 21097.16 100.000% 100.000% 82.4MB/sec [20081217-09:17:55.522434720] - [20081217-09:17:55.524803204] 21097.16 Transactions per Second [20081217-09:17:55.527082916] [20081217-09:17:55.529240507] Throughput Results [20081217-09:17:55.544097560] =================== [20081217-09:17:55.546208125] Read Throughput: 82.4MB/sec [20081217-09:17:55.548410193] [20081217-09:17:55.550721447] System Call Latency statistics in millisecs [20081217-09:17:55.553226298] ===== [20081217-09:17:55.555855298] Min Avg Max Total Calls [20081217-09:17:55.558176968] ======== ======== ======== ============ [20081217-09:17:55.560667280] [ open] 0.007000 19.655291 556.004028 715 [20081217-09:17:55.563051063] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:17:55.565304247] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:17:55.567407833] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:17:55.569636170] msec_range[3] 500.000000 - 1000.000000 : 1 [20081217-09:17:55.571728263] msec_range[4] 200.000000 - 500.000000 : 38 [20081217-09:17:55.573938501] msec_range[5] 100.000000 - 200.000000 : 14 [20081217-09:17:55.576130717] msec_range[6] 50.000000 - 100.000000 : 5 [20081217-09:17:55.578339006] msec_range[7] 20.000000 - 50.000000 : 5 [20081217-09:17:55.580452496] msec_range[8] 10.000000 - 20.000000 : 3 [20081217-09:17:55.626013379] msec_range[9] 5.000000 - 10.000000 : 1 [20081217-09:17:55.628225913] msec_range[10] 2.000000 - 5.000000 : 1 [20081217-09:17:55.630804208] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-09:17:55.632949569] msec_range[12] 0.500000 - 1.000000 : 2 [20081217-09:17:55.635553099] msec_range[13] 0.200000 - 0.500000 : 3 [20081217-09:17:55.639158470] msec_range[14] 0.100000 - 0.200000 : 16 [20081217-09:17:55.641700078] msec_range[15] 0.050000 - 0.100000 : 350 [20081217-09:17:55.644309649] msec_range[16] 0.020000 - 0.050000 : 269 [20081217-09:17:55.646955189] msec_range[17] 0.010000 - 0.020000 : 2 [20081217-09:17:55.649591946] msec_range[18] 0.000000 - 0.010000 : 5 [20081217-09:17:55.652754173] [20081217-09:17:55.655094552] [ read] 0.001000 0.373934 2856.878906 6406400 [20081217-09:17:55.657468893] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:17:55.660170629] msec_range[1] 2000.000000 - 5000.000000 : 49 [20081217-09:17:55.662441966] msec_range[2] 1000.000000 - 2000.000000 : 305 [20081217-09:17:55.664678499] msec_range[3] 500.000000 - 1000.000000 : 614 [20081217-09:17:55.666845859] msec_range[4] 200.000000 - 500.000000 : 2602 [20081217-09:17:55.669091276] msec_range[5] 100.000000 - 200.000000 : 1797 [20081217-09:17:55.671472032] msec_range[6] 50.000000 - 100.000000 : 1263 [20081217-09:17:55.673891001] msec_range[7] 20.000000 - 50.000000 : 1341 [20081217-09:17:55.676352809] msec_range[8] 10.000000 - 20.000000 : 733 [20081217-09:17:55.678658263] msec_range[9] 5.000000 - 10.000000 : 4725 [20081217-09:17:55.680829291] msec_range[10] 2.000000 - 5.000000 : 24493 [20081217-09:17:55.683102128] msec_range[11] 1.000000 - 2.000000 : 964 [20081217-09:17:55.685280864] msec_range[12] 0.500000 - 1.000000 : 300 [20081217-09:17:55.687721677] msec_range[13] 0.200000 - 0.500000 : 342 [20081217-09:17:55.690054870] msec_range[14] 0.100000 - 0.200000 : 884 [20081217-09:17:55.692377862] msec_range[15] 0.050000 - 0.100000 : 3123 [20081217-09:17:55.694488709] msec_range[16] 0.020000 - 0.050000 : 30097 [20081217-09:17:55.696665235] msec_range[17] 0.010000 - 0.020000 : 814464 [20081217-09:17:55.698838035] msec_range[18] 0.000000 - 0.010000 : 5518304 [20081217-09:17:55.701154721] [20081217-09:17:55.703346937] [ close] 0.003000 0.007578 0.051000 715 [20081217-09:17:55.705518439] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:17:55.707623460] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:17:55.709855542] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:17:55.712110959] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-09:17:55.714609766] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-09:17:55.716897771] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-09:17:55.719696674] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-09:17:55.722999809] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-09:17:55.726109416] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-09:17:55.728500080] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-09:17:55.730732335] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-09:17:55.733192015] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-09:17:55.735488886] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-09:17:55.737937594] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-09:17:55.740594914] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-09:17:55.742833215] msec_range[15] 0.050000 - 0.100000 : 1 [20081217-09:17:55.745915445] msec_range[16] 0.020000 - 0.050000 : 1 [20081217-09:17:55.748188143] msec_range[17] 0.010000 - 0.020000 : 127 [20081217-09:17:55.750386085] msec_range[18] 0.000000 - 0.010000 : 586 [20081217-09:17:55.752744260] [20081217-09:17:55.754952807] [20081217-09:17:55.757146618] [20081217-09:17:55.759227857] [20081217-09:17:55.761450685] 1.5% User Time [20081217-09:17:55.763536947] 25.8% System Time [20081217-09:17:55.765937329] 27.4% CPU Utilization [20081217-09:17:55.768086020] Profilers reporting [20081217-09:17:55.946227553] /autobench/scripts/doprofilers: line 33: 8822 Terminated ${CMDS[$i]} [20081217-09:17:55.978315086] /autobench/scripts/doprofilers: line 33: 8824 Terminated ${CMDS[$i]} [20081217-09:17:56.008627310] /autobench/scripts/doprofilers: line 33: 8849 Terminated ${CMDS[$i]} [20081217-09:18:11.899269039] Profilers postprocessing [20081217-09:18:12.180329763] Processing File : iostat.001 [20081217-09:18:12.182645767] Discovered iostat_interval=[5] [20081217-09:18:12.759762707] Processing Directory : sar.breakout.001 [20081217-09:18:12.761983929] Discovered sar_interval=[5] [20081217-09:18:12.928374872] Processing File : mpstat.001 [20081217-09:18:12.930472201] Discovered mpstat_interval=[5] [20081217-09:18:14.065618627] Stopping profiling. [20081217-09:18:14.070409054] Killing daemon. [20081217-09:18:16.343312054] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0008.08-12-17_09.12.42/analysis/oprofile.001 [20081217-09:18:16.345659084] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0008.08-12-17_09.12.42/analysis/oprofile-brief.001 [20081217-09:18:18.000418993] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-17_0900/btrfs-baseline' [20081217-09:18:20.017402159] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-09:18:21.702476624] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-09:18:21.922085923] PROCESSING COMMAND : 'run sequential_reads__threads_0032 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb num_threads=32' [20081217-09:18:21.965469551] new log requested [20081217-09:18:21.988008060] Running command ffsb [20081217-09:18:30.081351336] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb [20081217-09:18:30.094361198] Importing argument : num_threads=32 [20081217-09:18:30.120139079] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-09:18:30.199189634] FFSB version 6.0-RC2 started [20081217-09:18:30.201251706] [20081217-09:18:30.320053908] benchmark time = 300 [20081217-09:18:30.322229341] ThreadGroup 0 [20081217-09:18:30.324168277] ================ [20081217-09:18:30.326067934] num_threads = 32 [20081217-09:18:30.327911991] [20081217-09:18:30.329705137] read_random = off [20081217-09:18:30.331534536] read_size = 0 (0B) [20081217-09:18:30.333326350] read_blocksize = 4096 (4KB) [20081217-09:18:30.335163636] read_skip = off [20081217-09:18:30.336956053] read_skipsize = 0 (0B) [20081217-09:18:30.338778626] [20081217-09:18:30.340522396] write_random = off [20081217-09:18:30.342345334] write_size = 0 (0B) [20081217-09:18:30.344066777] fsync_file = 0 [20081217-09:18:30.345872917] write_blocksize = 0 (0B) [20081217-09:18:30.347596275] wait time = 0 [20081217-09:18:30.349403765] [20081217-09:18:30.351118451] op weights [20081217-09:18:30.352857466] read = 0 (0.00%) [20081217-09:18:30.354612644] readall = 1 (100.00%) [20081217-09:18:30.356405331] write = 0 (0.00%) [20081217-09:18:30.358110993] create = 0 (0.00%) [20081217-09:18:30.359890996] append = 0 (0.00%) [20081217-09:18:30.361671081] delete = 0 (0.00%) [20081217-09:18:30.363481409] metaop = 0 (0.00%) [20081217-09:18:30.365211504] createdir = 0 (0.00%) [20081217-09:18:30.366990617] stat = 0 (0.00%) [20081217-09:18:30.368702783] writeall = 0 (0.00%) [20081217-09:18:30.370486651] writeall_fsync = 0 (0.00%) [20081217-09:18:30.372187687] open_close = 0 (0.00%) [20081217-09:18:30.374047011] write_fsync = 0 (0.00%) [20081217-09:18:30.375772194] create_fsync = 0 (0.00%) [20081217-09:18:30.377561980] append_fsync = 0 (0.00%) [20081217-09:18:30.379299661] [20081217-09:18:30.381086586] FileSystem /mnt/ffsb1 [20081217-09:18:30.382796293] ========== [20081217-09:18:30.384590269] num_dirs = 0 [20081217-09:18:30.386328550] starting files = 1024 [20081217-09:18:30.388097502] [20081217-09:18:30.389839095] min file size = 36700160 (35MB) [20081217-09:18:30.391625907] max file size = 36700160 (35MB) [20081217-09:18:30.393353058] directio = off [20081217-09:18:30.395121446] alignedio = on [20081217-09:18:30.396827140] bufferedio = off [20081217-09:18:30.398610912] [20081217-09:18:30.400323171] aging is off [20081217-09:18:30.402106664] current utilization = 51.26% [20081217-09:18:30.403824048] [20081217-09:18:30.405614385] checking existing fs: /mnt/ffsb1 [20081217-09:18:30.969691557] fs setup took 0 secs [20081217-09:18:31.395304892] Syncing()...0 sec [20081217-09:18:31.397540698] Starting Actual Benchmark At: Wed Dec 17 09:18:31 2008 [20081217-09:18:31.410755380] [20081217-09:23:40.883367178] Syncing()...0 sec [20081217-09:23:40.911974397] FFSB benchmark finished at: Wed Dec 17 09:23:40 2008 [20081217-09:23:40.914894112] [20081217-09:23:40.917604079] Results: [20081217-09:23:40.956070808] Benchmark took 309.23 sec [20081217-09:23:40.958711258] [20081217-09:23:40.961458932] Total Results [20081217-09:23:40.976751196] =============== [20081217-09:23:40.978964244] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-09:23:40.981457914] ======= ============ ========= ======= =========== ========== [20081217-09:23:40.983742702] readall : 6128640 19818.86 100.000% 100.000% 77.4MB/sec [20081217-09:23:40.985904114] - [20081217-09:23:40.988191957] 19818.86 Transactions per Second [20081217-09:23:40.990620129] [20081217-09:23:40.993236703] Throughput Results [20081217-09:23:41.008805329] =================== [20081217-09:23:41.011360584] Read Throughput: 77.4MB/sec [20081217-09:23:41.013743125] [20081217-09:23:41.016066209] System Call Latency statistics in millisecs [20081217-09:23:41.018326186] ===== [20081217-09:23:41.020526004] Min Avg Max Total Calls [20081217-09:23:41.023057011] ======== ======== ======== ============ [20081217-09:23:41.025387000] [ open] 0.006000 52.849430 1127.642944 684 [20081217-09:23:41.027575409] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:23:41.029683069] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:23:41.031913645] msec_range[2] 1000.000000 - 2000.000000 : 2 [20081217-09:23:41.034013738] msec_range[3] 500.000000 - 1000.000000 : 37 [20081217-09:23:41.036239657] msec_range[4] 200.000000 - 500.000000 : 18 [20081217-09:23:41.038277419] msec_range[5] 100.000000 - 200.000000 : 8 [20081217-09:23:41.040483426] msec_range[6] 50.000000 - 100.000000 : 5 [20081217-09:23:41.042665139] msec_range[7] 20.000000 - 50.000000 : 5 [20081217-09:23:41.044852154] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-09:23:41.046989028] msec_range[9] 5.000000 - 10.000000 : 3 [20081217-09:23:41.049229155] msec_range[10] 2.000000 - 5.000000 : 2 [20081217-09:23:41.051301159] msec_range[11] 1.000000 - 2.000000 : 1 [20081217-09:23:41.053454279] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-09:23:41.055583927] msec_range[13] 0.200000 - 0.500000 : 1 [20081217-09:23:41.057813616] msec_range[14] 0.100000 - 0.200000 : 26 [20081217-09:23:41.059943601] msec_range[15] 0.050000 - 0.100000 : 282 [20081217-09:23:41.062106708] msec_range[16] 0.020000 - 0.050000 : 257 [20081217-09:23:41.064560638] msec_range[17] 0.010000 - 0.020000 : 16 [20081217-09:23:41.066749913] msec_range[18] 0.000000 - 0.010000 : 21 [20081217-09:23:41.101152387] [20081217-09:23:41.103380805] [ read] 0.001000 1.587766 5002.305176 6128640 [20081217-09:23:41.105495225] msec_range[0] 5000.000000 - 10000.000000 : 1 [20081217-09:23:41.107930192] msec_range[1] 2000.000000 - 5000.000000 : 358 [20081217-09:23:41.110095771] msec_range[2] 1000.000000 - 2000.000000 : 2871 [20081217-09:23:41.112250911] msec_range[3] 500.000000 - 1000.000000 : 5083 [20081217-09:23:41.114327820] msec_range[4] 200.000000 - 500.000000 : 2344 [20081217-09:23:41.116519677] msec_range[5] 100.000000 - 200.000000 : 1292 [20081217-09:23:41.118889966] msec_range[6] 50.000000 - 100.000000 : 1028 [20081217-09:23:41.121164696] msec_range[7] 20.000000 - 50.000000 : 1096 [20081217-09:23:41.123518555] msec_range[8] 10.000000 - 20.000000 : 610 [20081217-09:23:41.125683607] msec_range[9] 5.000000 - 10.000000 : 2842 [20081217-09:23:41.127907618] msec_range[10] 2.000000 - 5.000000 : 15480 [20081217-09:23:41.130065404] msec_range[11] 1.000000 - 2.000000 : 623 [20081217-09:23:41.132331001] msec_range[12] 0.500000 - 1.000000 : 317 [20081217-09:23:41.134466640] msec_range[13] 0.200000 - 0.500000 : 1452 [20081217-09:23:41.136718410] msec_range[14] 0.100000 - 0.200000 : 6134 [20081217-09:23:41.138803152] msec_range[15] 0.050000 - 0.100000 : 8499 [20081217-09:23:41.141061385] msec_range[16] 0.020000 - 0.050000 : 24583 [20081217-09:23:41.143319566] msec_range[17] 0.010000 - 0.020000 : 532511 [20081217-09:23:41.145465777] msec_range[18] 0.000000 - 0.010000 : 5521516 [20081217-09:23:41.147561498] [20081217-09:23:41.149822695] [ close] 0.003000 0.007614 0.018000 684 [20081217-09:23:41.152226376] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:23:41.154473988] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:23:41.156562667] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:23:41.158903228] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-09:23:41.161048622] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-09:23:41.163211341] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-09:23:41.165269423] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-09:23:41.167635176] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-09:23:41.170008322] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-09:23:41.172208973] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-09:23:41.174539771] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-09:23:41.177675141] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-09:23:41.180515062] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-09:23:41.183080553] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-09:23:41.185431322] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-09:23:41.187886499] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-09:23:41.190202272] msec_range[16] 0.020000 - 0.050000 : 0 [20081217-09:23:41.192353398] msec_range[17] 0.010000 - 0.020000 : 94 [20081217-09:23:41.194911689] msec_range[18] 0.000000 - 0.010000 : 590 [20081217-09:23:41.197607111] [20081217-09:23:41.199914656] [20081217-09:23:41.202375806] [20081217-09:23:41.204603364] [20081217-09:23:41.206855274] 1.5% User Time [20081217-09:23:41.209043803] 57.0% System Time [20081217-09:23:41.211267557] 58.5% CPU Utilization [20081217-09:23:41.259654540] Profilers reporting [20081217-09:23:41.486251122] /autobench/scripts/doprofilers: line 33: 14765 Terminated ${CMDS[$i]} [20081217-09:23:41.518224223] /autobench/scripts/doprofilers: line 33: 14794 Terminated ${CMDS[$i]} [20081217-09:24:00.940432632] Profilers postprocessing [20081217-09:24:01.222751744] Processing File : iostat.001 [20081217-09:24:01.225021536] Discovered iostat_interval=[5] [20081217-09:24:01.806613263] Processing Directory : sar.breakout.001 [20081217-09:24:01.808886975] Discovered sar_interval=[5] [20081217-09:24:01.974825019] Processing File : mpstat.001 [20081217-09:24:01.977093880] Discovered mpstat_interval=[5] [20081217-09:24:03.111159868] Stopping profiling. [20081217-09:24:03.116306060] Killing daemon. [20081217-09:24:05.676663479] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0032.08-12-17_09.18.21/analysis/oprofile.001 [20081217-09:24:05.678970644] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0032.08-12-17_09.18.21/analysis/oprofile-brief.001 [20081217-09:24:07.355068729] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-17_0900/btrfs-baseline' [20081217-09:24:09.373477699] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-09:24:11.092519194] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-09:24:11.317152886] PROCESSING COMMAND : 'run random_reads__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb num_threads=1' [20081217-09:24:11.361722961] new log requested [20081217-09:24:11.384475233] Running command ffsb [20081217-09:24:19.292978350] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb [20081217-09:24:19.305927608] Importing argument : num_threads=1 [20081217-09:24:19.331220062] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-09:24:19.410854600] FFSB version 6.0-RC2 started [20081217-09:24:19.413022005] [20081217-09:24:19.415149412] benchmark time = 300 [20081217-09:24:19.417275661] ThreadGroup 0 [20081217-09:24:19.419211148] ================ [20081217-09:24:19.420988819] num_threads = 1 [20081217-09:24:19.422825110] [20081217-09:24:19.424549379] read_random = on [20081217-09:24:19.426375723] read_size = 1048576 (1MB) [20081217-09:24:19.428156873] read_blocksize = 4096 (4KB) [20081217-09:24:19.430000564] read_skip = off [20081217-09:24:19.431729021] read_skipsize = 0 (0B) [20081217-09:24:19.433557469] [20081217-09:24:19.435291575] write_random = off [20081217-09:24:19.437107502] write_size = 0 (0B) [20081217-09:24:19.438853336] fsync_file = 0 [20081217-09:24:19.440644630] write_blocksize = 0 (0B) [20081217-09:24:19.442387236] wait time = 0 [20081217-09:24:19.444195762] [20081217-09:24:19.445921204] op weights [20081217-09:24:19.447700381] read = 1 (100.00%) [20081217-09:24:19.449441483] readall = 0 (0.00%) [20081217-09:24:19.451251444] write = 0 (0.00%) [20081217-09:24:19.452980369] create = 0 (0.00%) [20081217-09:24:19.454765574] append = 0 (0.00%) [20081217-09:24:19.456479806] delete = 0 (0.00%) [20081217-09:24:19.458330897] metaop = 0 (0.00%) [20081217-09:24:19.460082563] createdir = 0 (0.00%) [20081217-09:24:19.461898289] stat = 0 (0.00%) [20081217-09:24:19.463646260] writeall = 0 (0.00%) [20081217-09:24:19.465464793] writeall_fsync = 0 (0.00%) [20081217-09:24:19.467176117] open_close = 0 (0.00%) [20081217-09:24:19.468975188] write_fsync = 0 (0.00%) [20081217-09:24:19.470698798] create_fsync = 0 (0.00%) [20081217-09:24:19.472500133] append_fsync = 0 (0.00%) [20081217-09:24:19.474214158] [20081217-09:24:19.476006949] FileSystem /mnt/ffsb1 [20081217-09:24:19.477739961] ========== [20081217-09:24:19.479555058] num_dirs = 0 [20081217-09:24:19.481276678] starting files = 1024 [20081217-09:24:19.483087665] [20081217-09:24:19.484805070] min file size = 36700160 (35MB) [20081217-09:24:19.486630824] max file size = 36700160 (35MB) [20081217-09:24:19.488378661] directio = off [20081217-09:24:19.490176890] alignedio = on [20081217-09:24:19.491910213] bufferedio = off [20081217-09:24:19.493720711] [20081217-09:24:19.495444181] aging is off [20081217-09:24:19.497240130] current utilization = 51.26% [20081217-09:24:19.498979435] [20081217-09:24:19.500815326] checking existing fs: /mnt/ffsb1 [20081217-09:24:20.062986579] fs setup took 0 secs [20081217-09:24:20.427407854] Syncing()...0 sec [20081217-09:24:20.429270972] Starting Actual Benchmark At: Wed Dec 17 09:24:20 2008 [20081217-09:24:20.442345443] [20081217-09:29:22.536487648] Syncing()...0 sec [20081217-09:29:22.539219342] FFSB benchmark finished at: Wed Dec 17 09:29:22 2008 [20081217-09:29:22.542142510] [20081217-09:29:22.544888410] Results: [20081217-09:29:22.560225990] Benchmark took 302.11 sec [20081217-09:29:22.562610910] [20081217-09:29:22.565253030] Total Results [20081217-09:29:22.580654090] =============== [20081217-09:29:22.583349375] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-09:29:22.586042447] ======= ============ ========= ======= =========== ========== [20081217-09:29:22.588450764] read : 100608 333.02 100.000% 100.000% 1.3MB/sec [20081217-09:29:22.591496231] - [20081217-09:29:22.594332098] 333.02 Transactions per Second [20081217-09:29:22.596833132] [20081217-09:29:22.600047914] Throughput Results [20081217-09:29:22.616492071] =================== [20081217-09:29:22.619072091] Read Throughput: 1.3MB/sec [20081217-09:29:22.621460295] [20081217-09:29:22.624039829] System Call Latency statistics in millisecs [20081217-09:29:22.626935311] ===== [20081217-09:29:22.629968941] Min Avg Max Total Calls [20081217-09:29:22.632598015] ======== ======== ======== ============ [20081217-09:29:22.635168848] [ open] 0.010000 0.014142 0.028000 393 [20081217-09:29:22.637777185] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:29:22.640395948] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:29:22.642804353] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:29:22.645040634] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-09:29:22.647709891] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-09:29:22.650462484] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-09:29:22.652918039] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-09:29:22.655464043] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-09:29:22.659425586] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-09:29:22.663127487] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-09:29:22.667482413] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-09:29:22.670516004] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-09:29:22.673383018] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-09:29:22.676281268] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-09:29:22.678998869] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-09:29:22.682265982] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-09:29:22.684921265] msec_range[16] 0.020000 - 0.050000 : 14 [20081217-09:29:22.687583310] msec_range[17] 0.010000 - 0.020000 : 379 [20081217-09:29:22.690194829] msec_range[18] 0.000000 - 0.010000 : 0 [20081217-09:29:22.693037300] [20081217-09:29:22.695657366] [ read] 0.002000 2.994331 108.026001 100608 [20081217-09:29:22.698961401] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:29:22.701145679] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:29:22.703728934] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:29:22.706307232] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-09:29:22.708528888] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-09:29:22.710887026] msec_range[5] 100.000000 - 200.000000 : 1 [20081217-09:29:22.715774036] msec_range[6] 50.000000 - 100.000000 : 9 [20081217-09:29:22.718370763] msec_range[7] 20.000000 - 50.000000 : 121 [20081217-09:29:22.720704723] msec_range[8] 10.000000 - 20.000000 : 2300 [20081217-09:29:22.722891139] msec_range[9] 5.000000 - 10.000000 : 953 [20081217-09:29:22.726680991] msec_range[10] 2.000000 - 5.000000 : 64154 [20081217-09:29:22.729224918] msec_range[11] 1.000000 - 2.000000 : 20788 [20081217-09:29:22.733760312] msec_range[12] 0.500000 - 1.000000 : 412 [20081217-09:29:22.736213289] msec_range[13] 0.200000 - 0.500000 : 9421 [20081217-09:29:22.738913548] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-09:29:22.742164555] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-09:29:22.744668303] msec_range[16] 0.020000 - 0.050000 : 1 [20081217-09:29:22.747190218] msec_range[17] 0.010000 - 0.020000 : 49 [20081217-09:29:22.751307846] msec_range[18] 0.000000 - 0.010000 : 2399 [20081217-09:29:22.753921149] [20081217-09:29:22.758087224] [ lseek] 0.000000 0.001228 0.017000 100608 [20081217-09:29:22.760535282] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:29:22.763038418] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:29:22.767276051] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:29:22.770154901] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-09:29:22.772536415] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-09:29:22.774839028] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-09:29:22.777516863] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-09:29:22.780502966] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-09:29:22.783034294] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-09:29:22.785531042] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-09:29:22.787991336] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-09:29:22.790637194] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-09:29:22.793187131] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-09:29:22.795767467] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-09:29:22.798356646] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-09:29:22.800866335] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-09:29:22.803425304] msec_range[16] 0.020000 - 0.050000 : 0 [20081217-09:29:22.805762571] msec_range[17] 0.010000 - 0.020000 : 4 [20081217-09:29:22.808239784] msec_range[18] 0.000000 - 0.010000 : 100604 [20081217-09:29:22.810614787] [20081217-09:29:22.813098961] [ close] 0.003000 0.004489 0.015000 393 [20081217-09:29:22.816272024] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:29:22.818595637] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:29:22.820962493] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:29:22.823305436] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-09:29:22.825837719] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-09:29:22.828612776] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-09:29:22.831210471] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-09:29:22.833712995] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-09:29:22.836253619] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-09:29:22.838692691] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-09:29:22.841002484] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-09:29:22.843437329] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-09:29:22.845986100] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-09:29:22.848219656] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-09:29:22.850391381] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-09:29:22.852699607] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-09:29:22.854916116] msec_range[16] 0.020000 - 0.050000 : 0 [20081217-09:29:22.857057669] msec_range[17] 0.010000 - 0.020000 : 2 [20081217-09:29:22.859337175] msec_range[18] 0.000000 - 0.010000 : 391 [20081217-09:29:22.861542334] [20081217-09:29:22.863612443] [20081217-09:29:22.865846155] [20081217-09:29:22.868101096] [20081217-09:29:22.870322041] 0.1% User Time [20081217-09:29:22.872728326] 1.6% System Time [20081217-09:29:22.875091749] 1.7% CPU Utilization [20081217-09:29:22.877473589] Profilers reporting [20081217-09:29:22.879808482] /autobench/scripts/doprofilers: line 33: 20542 Terminated ${CMDS[$i]} [20081217-09:29:22.882034463] /autobench/scripts/doprofilers: line 33: 20552 Terminated ${CMDS[$i]} [20081217-09:29:22.884317566] /autobench/scripts/doprofilers: line 33: 20588 Terminated ${CMDS[$i]} [20081217-09:29:34.242809143] Profilers postprocessing [20081217-09:29:34.329165972] Processing File : iostat.001 [20081217-09:29:34.331293878] Discovered iostat_interval=[5] [20081217-09:29:34.856502098] Processing Directory : sar.breakout.001 [20081217-09:29:34.858799161] Discovered sar_interval=[5] [20081217-09:29:35.018755970] Processing File : mpstat.001 [20081217-09:29:35.020932413] Discovered mpstat_interval=[5] [20081217-09:29:36.154981887] Stopping profiling. [20081217-09:29:36.159612236] Killing daemon. [20081217-09:29:37.328670455] Processing File : /autobench/logs/ffsb.random_reads__threads_0001.08-12-17_09.24.11/analysis/oprofile.001 [20081217-09:29:37.330875119] Processing File : /autobench/logs/ffsb.random_reads__threads_0001.08-12-17_09.24.11/analysis/oprofile-brief.001 [20081217-09:29:38.801167593] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-17_0900/btrfs-baseline' [20081217-09:29:40.248185696] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-09:29:40.948693401] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-09:29:41.230112834] PROCESSING COMMAND : 'run random_reads__threads_0008 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb num_threads=8' [20081217-09:29:41.273333219] new log requested [20081217-09:29:41.295725706] Running command ffsb [20081217-09:29:48.590777614] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb [20081217-09:29:48.603548792] Importing argument : num_threads=8 [20081217-09:29:48.629625794] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-09:29:48.694717898] FFSB version 6.0-RC2 started [20081217-09:29:48.696752671] [20081217-09:29:48.726099437] benchmark time = 300 [20081217-09:29:48.728357689] ThreadGroup 0 [20081217-09:29:48.730173743] ================ [20081217-09:29:48.732433495] num_threads = 8 [20081217-09:29:48.734304284] [20081217-09:29:48.736212676] read_random = on [20081217-09:29:48.737963411] read_size = 1048576 (1MB) [20081217-09:29:48.739806805] read_blocksize = 4096 (4KB) [20081217-09:29:48.741585590] read_skip = off [20081217-09:29:48.743448918] read_skipsize = 0 (0B) [20081217-09:29:48.745200373] [20081217-09:29:48.747026115] write_random = off [20081217-09:29:48.748800430] write_size = 0 (0B) [20081217-09:29:48.750623923] fsync_file = 0 [20081217-09:29:48.752346957] write_blocksize = 0 (0B) [20081217-09:29:48.754191500] wait time = 0 [20081217-09:29:48.755945548] [20081217-09:29:48.757752540] op weights [20081217-09:29:48.759467536] read = 1 (100.00%) [20081217-09:29:48.761267593] readall = 0 (0.00%) [20081217-09:29:48.763014782] write = 0 (0.00%) [20081217-09:29:48.764827626] create = 0 (0.00%) [20081217-09:29:48.766602945] append = 0 (0.00%) [20081217-09:29:48.768399010] delete = 0 (0.00%) [20081217-09:29:48.770136367] metaop = 0 (0.00%) [20081217-09:29:48.772021516] createdir = 0 (0.00%) [20081217-09:29:48.773795159] stat = 0 (0.00%) [20081217-09:29:48.775637764] writeall = 0 (0.00%) [20081217-09:29:48.777379470] writeall_fsync = 0 (0.00%) [20081217-09:29:48.779227516] open_close = 0 (0.00%) [20081217-09:29:48.780957094] write_fsync = 0 (0.00%) [20081217-09:29:48.782772232] create_fsync = 0 (0.00%) [20081217-09:29:48.784524068] append_fsync = 0 (0.00%) [20081217-09:29:48.786323668] [20081217-09:29:48.787995522] FileSystem /mnt/ffsb1 [20081217-09:29:48.789823565] ========== [20081217-09:29:48.791554532] num_dirs = 0 [20081217-09:29:48.793372248] starting files = 1024 [20081217-09:29:48.795115142] [20081217-09:29:48.796920981] min file size = 36700160 (35MB) [20081217-09:29:48.798674995] max file size = 36700160 (35MB) [20081217-09:29:48.800489087] directio = off [20081217-09:29:48.802231217] alignedio = on [20081217-09:29:48.804045068] bufferedio = off [20081217-09:29:48.805764787] [20081217-09:29:48.807571295] aging is off [20081217-09:29:48.809279019] current utilization = 51.26% [20081217-09:29:48.811073988] [20081217-09:29:48.812808044] checking existing fs: /mnt/ffsb1 [20081217-09:29:49.541795318] fs setup took 0 secs [20081217-09:29:50.587779726] Syncing()...1 sec [20081217-09:29:50.590052429] Starting Actual Benchmark At: Wed Dec 17 09:29:50 2008 [20081217-09:29:50.603221695] [20081217-09:34:54.133013424] Syncing()...0 sec [20081217-09:34:54.135849015] FFSB benchmark finished at: Wed Dec 17 09:34:54 2008 [20081217-09:34:54.138719656] [20081217-09:34:54.141353430] Results: [20081217-09:34:54.157525986] Benchmark took 303.54 sec [20081217-09:34:54.160490307] [20081217-09:34:54.163049533] Total Results [20081217-09:34:54.178691748] =============== [20081217-09:34:54.181382297] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-09:34:54.184135181] ======= ============ ========= ======= =========== ========== [20081217-09:34:54.186949489] read : 117760 387.95 100.000% 100.000% 1.52MB/sec [20081217-09:34:54.190429737] - [20081217-09:34:54.193457384] 387.95 Transactions per Second [20081217-09:34:54.196340526] [20081217-09:34:54.199161142] Throughput Results [20081217-09:34:54.214849833] =================== [20081217-09:34:54.217639107] Read Throughput: 1.52MB/sec [20081217-09:34:54.219971343] [20081217-09:34:54.222066606] System Call Latency statistics in millisecs [20081217-09:34:54.224543260] ===== [20081217-09:34:54.226994682] Min Avg Max Total Calls [20081217-09:34:54.231758148] ======== ======== ======== ============ [20081217-09:34:54.235258460] [ open] 0.007000 0.021324 0.418000 460 [20081217-09:34:54.239029670] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:34:54.243966280] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:34:54.247172306] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:34:54.249964638] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-09:34:54.252745540] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-09:34:54.255451257] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-09:34:54.258081638] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-09:34:54.261605759] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-09:34:54.266249718] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-09:34:54.268721463] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-09:34:54.271232048] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-09:34:54.274174728] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-09:34:54.276868331] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-09:34:54.279427780] msec_range[13] 0.200000 - 0.500000 : 1 [20081217-09:34:54.282085744] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-09:34:54.284631164] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-09:34:54.287253135] msec_range[16] 0.020000 - 0.050000 : 259 [20081217-09:34:54.289659029] msec_range[17] 0.010000 - 0.020000 : 181 [20081217-09:34:54.292846639] msec_range[18] 0.000000 - 0.010000 : 19 [20081217-09:34:54.295544794] [20081217-09:34:54.298380476] [ read] 0.002000 20.490555 2133.283936 117760 [20081217-09:34:54.301327494] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:34:54.304571022] msec_range[1] 2000.000000 - 5000.000000 : 17 [20081217-09:34:54.308740176] msec_range[2] 1000.000000 - 2000.000000 : 18 [20081217-09:34:54.311375157] msec_range[3] 500.000000 - 1000.000000 : 16 [20081217-09:34:54.314157802] msec_range[4] 200.000000 - 500.000000 : 540 [20081217-09:34:54.316945464] msec_range[5] 100.000000 - 200.000000 : 3256 [20081217-09:34:54.319482226] msec_range[6] 50.000000 - 100.000000 : 8869 [20081217-09:34:54.321945489] msec_range[7] 20.000000 - 50.000000 : 19586 [20081217-09:34:54.324638259] msec_range[8] 10.000000 - 20.000000 : 18373 [20081217-09:34:54.327493358] msec_range[9] 5.000000 - 10.000000 : 18613 [20081217-09:34:54.330141104] msec_range[10] 2.000000 - 5.000000 : 32883 [20081217-09:34:54.332929860] msec_range[11] 1.000000 - 2.000000 : 12447 [20081217-09:34:54.337282324] msec_range[12] 0.500000 - 1.000000 : 413 [20081217-09:34:54.339944151] msec_range[13] 0.200000 - 0.500000 : 396 [20081217-09:34:54.342701577] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-09:34:54.345443475] msec_range[15] 0.050000 - 0.100000 : 1 [20081217-09:34:54.348641275] msec_range[16] 0.020000 - 0.050000 : 23 [20081217-09:34:54.351120553] msec_range[17] 0.010000 - 0.020000 : 382 [20081217-09:34:54.353605139] msec_range[18] 0.000000 - 0.010000 : 1927 [20081217-09:34:54.356036968] [20081217-09:34:54.358434202] [ lseek] 0.000000 0.001419 0.139000 117760 [20081217-09:34:54.360990087] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:34:54.363523886] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:34:54.366843253] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:34:54.371009816] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-09:34:54.374606928] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-09:34:54.377769600] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-09:34:54.380734150] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-09:34:54.383573419] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-09:34:54.386360742] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-09:34:54.388990644] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-09:34:54.391619026] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-09:34:54.396153835] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-09:34:54.398941150] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-09:34:54.401779887] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-09:34:54.404482852] msec_range[14] 0.100000 - 0.200000 : 1 [20081217-09:34:54.407102004] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-09:34:54.409741693] msec_range[16] 0.020000 - 0.050000 : 1 [20081217-09:34:54.412549589] msec_range[17] 0.010000 - 0.020000 : 60 [20081217-09:34:54.416037184] msec_range[18] 0.000000 - 0.010000 : 117698 [20081217-09:34:54.419971183] [20081217-09:34:54.423333748] [ close] 0.002000 0.006117 0.023000 460 [20081217-09:34:54.425979420] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:34:54.428604108] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:34:54.431136693] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:34:54.435566700] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-09:34:54.438324626] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-09:34:54.440821764] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-09:34:54.443321893] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-09:34:54.446915334] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-09:34:54.449456458] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-09:34:54.451890006] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-09:34:54.454563282] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-09:34:54.457135120] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-09:34:54.459584392] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-09:34:54.461916464] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-09:34:54.464411060] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-09:34:54.466974228] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-09:34:54.469308888] msec_range[16] 0.020000 - 0.050000 : 1 [20081217-09:34:54.471602437] msec_range[17] 0.010000 - 0.020000 : 57 [20081217-09:34:54.473853848] msec_range[18] 0.000000 - 0.010000 : 402 [20081217-09:34:54.476147910] [20081217-09:34:54.478239445] [20081217-09:34:54.480439917] [20081217-09:34:54.482822121] [20081217-09:34:54.485237547] 0.1% User Time [20081217-09:34:54.487660141] 2.9% System Time [20081217-09:34:54.490021273] 3.0% CPU Utilization [20081217-09:34:54.492225917] Profilers reporting [20081217-09:34:54.494449352] /autobench/scripts/doprofilers: line 33: 26448 Terminated ${CMDS[$i]} [20081217-09:34:54.496567409] /autobench/scripts/doprofilers: line 33: 26493 Terminated ${CMDS[$i]} [20081217-09:35:07.457963464] Profilers postprocessing [20081217-09:35:07.544970295] Processing File : iostat.001 [20081217-09:35:07.547374384] Discovered iostat_interval=[5] [20081217-09:35:08.075326575] Processing Directory : sar.breakout.001 [20081217-09:35:08.077470113] Discovered sar_interval=[5] [20081217-09:35:08.237134679] Processing File : mpstat.001 [20081217-09:35:08.239319716] Discovered mpstat_interval=[5] [20081217-09:35:09.375456539] Stopping profiling. [20081217-09:35:09.379746698] Killing daemon. [20081217-09:35:10.551982968] Processing File : /autobench/logs/ffsb.random_reads__threads_0008.08-12-17_09.29.41/analysis/oprofile.001 [20081217-09:35:10.554127267] Processing File : /autobench/logs/ffsb.random_reads__threads_0008.08-12-17_09.29.41/analysis/oprofile-brief.001 [20081217-09:35:11.589310966] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-17_0900/btrfs-baseline' [20081217-09:35:13.049979542] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-09:35:13.824901037] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-09:35:14.078912450] PROCESSING COMMAND : 'run random_reads__threads_0032 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb num_threads=32' [20081217-09:35:14.122520217] new log requested [20081217-09:35:14.145327076] Running command ffsb [20081217-09:35:21.451634359] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb [20081217-09:35:21.464518959] Importing argument : num_threads=32 [20081217-09:35:21.490715470] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-09:35:21.555590310] FFSB version 6.0-RC2 started [20081217-09:35:21.557817636] [20081217-09:35:21.679153729] benchmark time = 300 [20081217-09:35:21.681402158] ThreadGroup 0 [20081217-09:35:21.683278051] ================ [20081217-09:35:21.685099724] num_threads = 32 [20081217-09:35:21.686889089] [20081217-09:35:21.688816414] read_random = on [20081217-09:35:21.690583432] read_size = 1048576 (1MB) [20081217-09:35:21.692396824] read_blocksize = 4096 (4KB) [20081217-09:35:21.694137908] read_skip = off [20081217-09:35:21.696029440] read_skipsize = 0 (0B) [20081217-09:35:21.697798370] [20081217-09:35:21.699631607] write_random = off [20081217-09:35:21.701375808] write_size = 0 (0B) [20081217-09:35:21.703274193] fsync_file = 0 [20081217-09:35:21.705019896] write_blocksize = 0 (0B) [20081217-09:35:21.706822352] wait time = 0 [20081217-09:35:21.708530114] [20081217-09:35:21.710346547] op weights [20081217-09:35:21.712092605] read = 1 (100.00%) [20081217-09:35:21.713830181] readall = 0 (0.00%) [20081217-09:35:21.715588673] write = 0 (0.00%) [20081217-09:35:21.717432462] create = 0 (0.00%) [20081217-09:35:21.719166236] append = 0 (0.00%) [20081217-09:35:21.720987922] delete = 0 (0.00%) [20081217-09:35:21.722745124] metaop = 0 (0.00%) [20081217-09:35:21.724557178] createdir = 0 (0.00%) [20081217-09:35:21.726289760] stat = 0 (0.00%) [20081217-09:35:21.728069216] writeall = 0 (0.00%) [20081217-09:35:21.729796936] writeall_fsync = 0 (0.00%) [20081217-09:35:21.731636002] open_close = 0 (0.00%) [20081217-09:35:21.733403213] write_fsync = 0 (0.00%) [20081217-09:35:21.735189584] create_fsync = 0 (0.00%) [20081217-09:35:21.736908671] append_fsync = 0 (0.00%) [20081217-09:35:21.738721447] [20081217-09:35:21.740458559] FileSystem /mnt/ffsb1 [20081217-09:35:21.742268732] ========== [20081217-09:35:21.743985861] num_dirs = 0 [20081217-09:35:21.745778278] starting files = 1024 [20081217-09:35:21.747527805] [20081217-09:35:21.749331760] min file size = 36700160 (35MB) [20081217-09:35:21.751070518] max file size = 36700160 (35MB) [20081217-09:35:21.752928823] directio = off [20081217-09:35:21.754671842] alignedio = on [20081217-09:35:21.756458143] bufferedio = off [20081217-09:35:21.758215071] [20081217-09:35:21.760015545] aging is off [20081217-09:35:21.761745630] current utilization = 51.26% [20081217-09:35:21.763542533] [20081217-09:35:21.765266859] checking existing fs: /mnt/ffsb1 [20081217-09:35:22.433107029] fs setup took 0 secs [20081217-09:35:23.520538589] Syncing()...1 sec [20081217-09:35:23.522802878] Starting Actual Benchmark At: Wed Dec 17 09:35:23 2008 [20081217-09:35:23.535928956] [20081217-09:40:32.660841172] Syncing()...1 sec [20081217-09:40:32.663616160] FFSB benchmark finished at: Wed Dec 17 09:40:32 2008 [20081217-09:40:32.667027616] [20081217-09:40:32.669679430] Results: [20081217-09:40:32.685451852] Benchmark took 309.14 sec [20081217-09:40:32.687991394] [20081217-09:40:32.690553102] Total Results [20081217-09:40:32.706341987] =============== [20081217-09:40:32.708851642] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-09:40:32.711721795] ======= ============ ========= ======= =========== ========== [20081217-09:40:32.716037154] read : 149760 484.44 100.000% 100.000% 1.89MB/sec [20081217-09:40:32.719222340] - [20081217-09:40:32.721662327] 484.44 Transactions per Second [20081217-09:40:32.724435694] [20081217-09:40:32.727937666] Throughput Results [20081217-09:40:32.745303024] =================== [20081217-09:40:32.747990728] Read Throughput: 1.89MB/sec [20081217-09:40:32.751125967] [20081217-09:40:32.753764124] System Call Latency statistics in millisecs [20081217-09:40:32.756134304] ===== [20081217-09:40:32.758546598] Min Avg Max Total Calls [20081217-09:40:32.762091298] ======== ======== ======== ============ [20081217-09:40:32.765829579] [ open] 0.006000 0.020103 0.038000 585 [20081217-09:40:32.768657916] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:40:32.771548039] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:40:32.775023332] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:40:32.778034561] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-09:40:32.780645431] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-09:40:32.784108092] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-09:40:32.786855248] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-09:40:32.789562077] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-09:40:32.793191456] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-09:40:32.796111486] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-09:40:32.802257874] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-09:40:32.805183578] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-09:40:32.807996288] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-09:40:32.810446300] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-09:40:32.813098167] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-09:40:32.815879712] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-09:40:32.818192596] msec_range[16] 0.020000 - 0.050000 : 326 [20081217-09:40:32.820742720] msec_range[17] 0.010000 - 0.020000 : 228 [20081217-09:40:32.823392495] msec_range[18] 0.000000 - 0.010000 : 31 [20081217-09:40:32.826946134] [20081217-09:40:32.829635987] [ read] 0.002000 65.131012 2455.248047 149760 [20081217-09:40:32.832605523] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:40:32.837810026] msec_range[1] 2000.000000 - 5000.000000 : 26 [20081217-09:40:32.840518161] msec_range[2] 1000.000000 - 2000.000000 : 207 [20081217-09:40:32.843238689] msec_range[3] 500.000000 - 1000.000000 : 1729 [20081217-09:40:32.845812332] msec_range[4] 200.000000 - 500.000000 : 9767 [20081217-09:40:32.848690519] msec_range[5] 100.000000 - 200.000000 : 15838 [20081217-09:40:32.851353277] msec_range[6] 50.000000 - 100.000000 : 21301 [20081217-09:40:32.855017973] msec_range[7] 20.000000 - 50.000000 : 33164 [20081217-09:40:32.857348073] msec_range[8] 10.000000 - 20.000000 : 24854 [20081217-09:40:32.859513790] msec_range[9] 5.000000 - 10.000000 : 19006 [20081217-09:40:32.865732432] msec_range[10] 2.000000 - 5.000000 : 16288 [20081217-09:40:32.868596826] msec_range[11] 1.000000 - 2.000000 : 4072 [20081217-09:40:32.870851320] msec_range[12] 0.500000 - 1.000000 : 76 [20081217-09:40:32.873310035] msec_range[13] 0.200000 - 0.500000 : 25 [20081217-09:40:32.875950119] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-09:40:32.879261801] msec_range[15] 0.050000 - 0.100000 : 2 [20081217-09:40:32.881796885] msec_range[16] 0.020000 - 0.050000 : 54 [20081217-09:40:32.884437887] msec_range[17] 0.010000 - 0.020000 : 633 [20081217-09:40:32.887474077] msec_range[18] 0.000000 - 0.010000 : 2718 [20081217-09:40:32.890365285] [20081217-09:40:32.893169203] [ lseek] 0.000000 0.001536 1.355000 149760 [20081217-09:40:32.895878690] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:40:32.898570591] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:40:32.901230067] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:40:32.904380277] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-09:40:32.907781047] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-09:40:32.910464246] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-09:40:32.913096431] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-09:40:32.915650029] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-09:40:32.918253957] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-09:40:32.920947503] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-09:40:32.924368407] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-09:40:32.927646542] msec_range[11] 1.000000 - 2.000000 : 1 [20081217-09:40:32.930297031] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-09:40:32.932829732] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-09:40:32.936615337] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-09:40:32.939357826] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-09:40:32.941834574] msec_range[16] 0.020000 - 0.050000 : 1 [20081217-09:40:32.944505414] msec_range[17] 0.010000 - 0.020000 : 80 [20081217-09:40:32.948236966] msec_range[18] 0.000000 - 0.010000 : 149678 [20081217-09:40:32.951840523] [20081217-09:40:32.954405104] [ close] 0.002000 0.005841 0.019000 585 [20081217-09:40:32.957066351] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:40:32.959459082] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:40:32.962596492] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:40:32.964899967] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-09:40:32.967356023] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-09:40:32.970729206] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-09:40:32.974540524] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-09:40:32.977048813] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-09:40:32.979591704] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-09:40:32.982026539] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-09:40:32.984646056] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-09:40:32.987348125] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-09:40:32.990035754] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-09:40:32.992587676] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-09:40:32.994775219] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-09:40:32.997223745] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-09:40:32.999544546] msec_range[16] 0.020000 - 0.050000 : 0 [20081217-09:40:33.001779160] msec_range[17] 0.010000 - 0.020000 : 58 [20081217-09:40:33.004202173] msec_range[18] 0.000000 - 0.010000 : 527 [20081217-09:40:33.006409152] [20081217-09:40:33.008664702] [20081217-09:40:33.011125559] [20081217-09:40:33.013514396] [20081217-09:40:33.015796565] 0.1% User Time [20081217-09:40:33.017973936] 3.8% System Time [20081217-09:40:33.020247639] 3.9% CPU Utilization [20081217-09:40:33.022452415] Profilers reporting [20081217-09:40:33.024556852] /autobench/scripts/doprofilers: line 33: 32344 Terminated ${CMDS[$i]} [20081217-09:40:33.026794057] /autobench/scripts/doprofilers: line 33: 32354 Terminated ${CMDS[$i]} [20081217-09:40:33.029033365] /autobench/scripts/doprofilers: line 33: 32388 Terminated ${CMDS[$i]} [20081217-09:40:45.630339692] Profilers postprocessing [20081217-09:40:45.716571284] Processing File : iostat.001 [20081217-09:40:45.718745875] Discovered iostat_interval=[5] [20081217-09:40:46.249868237] Processing Directory : sar.breakout.001 [20081217-09:40:46.252061433] Discovered sar_interval=[5] [20081217-09:40:46.413066559] Processing File : mpstat.001 [20081217-09:40:46.415230492] Discovered mpstat_interval=[5] [20081217-09:40:47.549145547] Stopping profiling. [20081217-09:40:47.554472301] Killing daemon. [20081217-09:40:48.752831338] Processing File : /autobench/logs/ffsb.random_reads__threads_0032.08-12-17_09.35.14/analysis/oprofile.001 [20081217-09:40:48.755067486] Processing File : /autobench/logs/ffsb.random_reads__threads_0032.08-12-17_09.35.14/analysis/oprofile-brief.001 [20081217-09:40:49.717640341] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-17_0900/btrfs-baseline' [20081217-09:40:51.204436282] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-09:40:52.282180525] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-09:40:52.488537696] PROCESSING COMMAND : 'run random_writes__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb num_threads=1' [20081217-09:40:52.532298377] new log requested [20081217-09:40:52.554725927] Running command ffsb [20081217-09:40:59.833359466] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb [20081217-09:40:59.847070457] Importing argument : num_threads=1 [20081217-09:40:59.873786626] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-09:40:59.939093290] FFSB version 6.0-RC2 started [20081217-09:40:59.941163858] [20081217-09:40:59.943200372] benchmark time = 300 [20081217-09:40:59.945261434] ThreadGroup 0 [20081217-09:40:59.947093686] ================ [20081217-09:40:59.948925055] num_threads = 1 [20081217-09:40:59.950655494] [20081217-09:40:59.952466601] read_random = off [20081217-09:40:59.954235946] read_size = 0 (0B) [20081217-09:40:59.956099643] read_blocksize = 0 (0B) [20081217-09:40:59.957802489] read_skip = off [20081217-09:40:59.959838218] read_skipsize = 0 (0B) [20081217-09:40:59.962053543] [20081217-09:40:59.963891143] write_random = on [20081217-09:40:59.966072807] write_size = 1048576 (1MB) [20081217-09:40:59.968033285] fsync_file = 0 [20081217-09:40:59.969853113] write_blocksize = 4096 (4KB) [20081217-09:40:59.971615158] wait time = 0 [20081217-09:40:59.973509095] [20081217-09:40:59.975309891] op weights [20081217-09:40:59.977145959] read = 0 (0.00%) [20081217-09:40:59.978902287] readall = 0 (0.00%) [20081217-09:40:59.980742565] write = 1 (100.00%) [20081217-09:40:59.982473217] create = 0 (0.00%) [20081217-09:40:59.984309344] append = 0 (0.00%) [20081217-09:40:59.986061855] delete = 0 (0.00%) [20081217-09:40:59.987879035] metaop = 0 (0.00%) [20081217-09:40:59.989631137] createdir = 0 (0.00%) [20081217-09:40:59.991446274] stat = 0 (0.00%) [20081217-09:40:59.993199306] writeall = 0 (0.00%) [20081217-09:40:59.995002493] writeall_fsync = 0 (0.00%) [20081217-09:40:59.996732135] open_close = 0 (0.00%) [20081217-09:40:59.998533339] write_fsync = 0 (0.00%) [20081217-09:41:00.000272296] create_fsync = 0 (0.00%) [20081217-09:41:00.002131901] append_fsync = 0 (0.00%) [20081217-09:41:00.003871156] [20081217-09:41:00.005670682] FileSystem /mnt/ffsb1 [20081217-09:41:00.007398287] ========== [20081217-09:41:00.009185605] num_dirs = 0 [20081217-09:41:00.010927357] starting files = 1024 [20081217-09:41:00.012698495] [20081217-09:41:00.014408484] min file size = 36700160 (35MB) [20081217-09:41:00.016238692] max file size = 36700160 (35MB) [20081217-09:41:00.017967506] directio = off [20081217-09:41:00.019743236] alignedio = on [20081217-09:41:00.021460243] bufferedio = off [20081217-09:41:00.023319416] [20081217-09:41:00.025061713] aging is off [20081217-09:41:00.026845055] current utilization = 51.26% [20081217-09:41:00.028577112] [20081217-09:41:00.030388834] checking existing fs: /mnt/ffsb1 [20081217-09:41:00.527692606] fs setup took 0 secs [20081217-09:41:01.529996236] Syncing()...1 sec [20081217-09:41:01.532214063] Starting Actual Benchmark At: Wed Dec 17 09:41:01 2008 [20081217-09:41:01.545405732] [20081217-09:46:09.601030765] Syncing()...7 sec [20081217-09:46:09.659723497] FFSB benchmark finished at: Wed Dec 17 09:46:09 2008 [20081217-09:46:09.662586979] [20081217-09:46:09.665271575] Results: [20081217-09:46:09.705028223] Benchmark took 307.87 sec [20081217-09:46:09.707161245] [20081217-09:46:09.709701144] Total Results [20081217-09:46:09.725081320] =============== [20081217-09:46:09.727580730] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-09:46:09.730009984] ======= ============ ========= ======= =========== ========== [20081217-09:46:09.732504751] write : 802304 2605.98 100.000% 100.000% 356MB/sec [20081217-09:46:09.735279841] - [20081217-09:46:09.738442941] 2605.98 Transactions per Second [20081217-09:46:09.741428432] [20081217-09:46:09.743802042] Throughput Results [20081217-09:46:09.758810108] =================== [20081217-09:46:09.761101734] Write Throughput: 356MB/sec [20081217-09:46:09.763469900] [20081217-09:46:09.765767805] System Call Latency statistics in millisecs [20081217-09:46:09.767942779] ===== [20081217-09:46:09.770232804] Min Avg Max Total Calls [20081217-09:46:09.772412076] ======== ======== ======== ============ [20081217-09:46:09.774788036] [ open] 0.008000 0.100088 180.117004 3134 [20081217-09:46:09.777180066] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:46:09.779405568] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:46:09.814980939] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:46:09.817596467] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-09:46:09.819909019] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-09:46:09.822326816] msec_range[5] 100.000000 - 200.000000 : 1 [20081217-09:46:09.824538291] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-09:46:09.827085342] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-09:46:09.829473125] msec_range[8] 10.000000 - 20.000000 : 1 [20081217-09:46:09.831846249] msec_range[9] 5.000000 - 10.000000 : 1 [20081217-09:46:09.834396933] msec_range[10] 2.000000 - 5.000000 : 4 [20081217-09:46:09.836636115] msec_range[11] 1.000000 - 2.000000 : 3 [20081217-09:46:09.838892633] msec_range[12] 0.500000 - 1.000000 : 2 [20081217-09:46:09.841069376] msec_range[13] 0.200000 - 0.500000 : 6 [20081217-09:46:09.843328249] msec_range[14] 0.100000 - 0.200000 : 81 [20081217-09:46:09.850339108] msec_range[15] 0.050000 - 0.100000 : 476 [20081217-09:46:09.853083266] msec_range[16] 0.020000 - 0.050000 : 910 [20081217-09:46:09.855893737] msec_range[17] 0.010000 - 0.020000 : 1586 [20081217-09:46:09.858495509] msec_range[18] 0.000000 - 0.010000 : 63 [20081217-09:46:09.860967713] [20081217-09:46:09.863535755] [ write] 0.009000 0.370928 6926.319824 802304 [20081217-09:46:09.865932572] msec_range[0] 5000.000000 - 10000.000000 : 5 [20081217-09:46:09.868457822] msec_range[1] 2000.000000 - 5000.000000 : 28 [20081217-09:46:09.870993566] msec_range[2] 1000.000000 - 2000.000000 : 24 [20081217-09:46:09.873662867] msec_range[3] 500.000000 - 1000.000000 : 24 [20081217-09:46:09.875959085] msec_range[4] 200.000000 - 500.000000 : 27 [20081217-09:46:09.878245296] msec_range[5] 100.000000 - 200.000000 : 33 [20081217-09:46:09.880596616] msec_range[6] 50.000000 - 100.000000 : 86 [20081217-09:46:09.882912363] msec_range[7] 20.000000 - 50.000000 : 181 [20081217-09:46:09.885602627] msec_range[8] 10.000000 - 20.000000 : 541 [20081217-09:46:09.889702485] msec_range[9] 5.000000 - 10.000000 : 1502 [20081217-09:46:09.892270040] msec_range[10] 2.000000 - 5.000000 : 3565 [20081217-09:46:09.894595128] msec_range[11] 1.000000 - 2.000000 : 7262 [20081217-09:46:09.897085689] msec_range[12] 0.500000 - 1.000000 : 17301 [20081217-09:46:09.899514856] msec_range[13] 0.200000 - 0.500000 : 53123 [20081217-09:46:09.901774012] msec_range[14] 0.100000 - 0.200000 : 59253 [20081217-09:46:09.904221893] msec_range[15] 0.050000 - 0.100000 : 187702 [20081217-09:46:09.906756272] msec_range[16] 0.020000 - 0.050000 : 368281 [20081217-09:46:09.909116186] msec_range[17] 0.010000 - 0.020000 : 103345 [20081217-09:46:09.914222311] msec_range[18] 0.000000 - 0.010000 : 21 [20081217-09:46:09.916881547] [20081217-09:46:09.919582611] [ lseek] 0.000000 0.001315 1.009000 802304 [20081217-09:46:09.921960163] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:46:09.924533700] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:46:09.926996885] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:46:09.929394685] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-09:46:09.931720735] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-09:46:09.933928101] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-09:46:09.936177480] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-09:46:09.938363686] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-09:46:09.940711693] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-09:46:09.943175304] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-09:46:09.945476899] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-09:46:09.947719387] msec_range[11] 1.000000 - 2.000000 : 1 [20081217-09:46:09.950124694] msec_range[12] 0.500000 - 1.000000 : 9 [20081217-09:46:09.952454188] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-09:46:09.954631497] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-09:46:09.956908887] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-09:46:09.959188969] msec_range[16] 0.020000 - 0.050000 : 67 [20081217-09:46:09.961370915] msec_range[17] 0.010000 - 0.020000 : 507 [20081217-09:46:09.963665703] msec_range[18] 0.000000 - 0.010000 : 801720 [20081217-09:46:09.965917652] [20081217-09:46:09.968028135] [ close] 0.002000 0.005016 0.028000 3134 [20081217-09:46:09.970872634] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:46:09.973216871] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:46:09.975457048] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:46:09.978018272] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-09:46:09.980315296] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-09:46:09.982504467] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-09:46:09.984904554] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-09:46:09.987290712] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-09:46:09.989432010] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-09:46:09.991747116] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-09:46:09.994039273] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-09:46:09.996503196] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-09:46:09.999138886] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-09:46:10.003825443] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-09:46:10.006175531] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-09:46:10.008364003] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-09:46:10.010685838] msec_range[16] 0.020000 - 0.050000 : 2 [20081217-09:46:10.012823324] msec_range[17] 0.010000 - 0.020000 : 129 [20081217-09:46:10.015128678] msec_range[18] 0.000000 - 0.010000 : 3003 [20081217-09:46:10.017497510] [20081217-09:46:10.019696342] [20081217-09:46:10.022054487] [20081217-09:46:10.024227869] [20081217-09:46:10.026443714] 0.7% User Time [20081217-09:46:10.028607964] 20.3% System Time [20081217-09:46:10.030883830] 21.0% CPU Utilization [20081217-09:46:10.033213770] Profilers reporting [20081217-09:46:32.002186756] Profilers postprocessing [20081217-09:46:32.205503283] Processing File : iostat.001 [20081217-09:46:32.211929727] Discovered iostat_interval=[5] [20081217-09:46:33.009289989] Processing Directory : sar.breakout.001 [20081217-09:46:33.011506930] Discovered sar_interval=[5] [20081217-09:46:33.183643291] Processing File : mpstat.001 [20081217-09:46:33.185745453] Discovered mpstat_interval=[5] [20081217-09:46:34.318970110] Stopping profiling. [20081217-09:46:34.323781481] Killing daemon. [20081217-09:46:35.568783525] Processing File : /autobench/logs/ffsb.random_writes__threads_0001.08-12-17_09.40.52/analysis/oprofile.001 [20081217-09:46:35.571123295] Processing File : /autobench/logs/ffsb.random_writes__threads_0001.08-12-17_09.40.52/analysis/oprofile-brief.001 [20081217-09:46:41.373439245] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-17_0900/btrfs-baseline' [20081217-09:46:44.301392658] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-09:46:46.796254541] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-09:46:47.740532820] PROCESSING COMMAND : 'run random_writes__threads_0008 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb num_threads=8' [20081217-09:46:47.784911073] new log requested [20081217-09:46:47.808080615] Running command ffsb [20081217-09:46:55.970735946] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb [20081217-09:46:55.983878591] Importing argument : num_threads=8 [20081217-09:46:56.010467013] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-09:46:56.079955647] FFSB version 6.0-RC2 started [20081217-09:46:56.082208259] [20081217-09:46:56.111440277] benchmark time = 300 [20081217-09:46:56.113665526] ThreadGroup 0 [20081217-09:46:56.115552644] ================ [20081217-09:46:56.117433041] num_threads = 8 [20081217-09:46:56.119232952] [20081217-09:46:56.121118466] read_random = off [20081217-09:46:56.122941054] read_size = 0 (0B) [20081217-09:46:56.124759711] read_blocksize = 0 (0B) [20081217-09:46:56.126558490] read_skip = off [20081217-09:46:56.128415952] read_skipsize = 0 (0B) [20081217-09:46:56.130125791] [20081217-09:46:56.131956323] write_random = on [20081217-09:46:56.133707920] write_size = 1048576 (1MB) [20081217-09:46:56.135566575] fsync_file = 0 [20081217-09:46:56.137316030] write_blocksize = 4096 (4KB) [20081217-09:46:56.139138040] wait time = 0 [20081217-09:46:56.140882975] [20081217-09:46:56.142735722] op weights [20081217-09:46:56.144496118] read = 0 (0.00%) [20081217-09:46:56.146342919] readall = 0 (0.00%) [20081217-09:46:56.148106010] write = 1 (100.00%) [20081217-09:46:56.149928488] create = 0 (0.00%) [20081217-09:46:56.151698291] append = 0 (0.00%) [20081217-09:46:56.153521724] delete = 0 (0.00%) [20081217-09:46:56.155279945] metaop = 0 (0.00%) [20081217-09:46:56.157097444] createdir = 0 (0.00%) [20081217-09:46:56.158898751] stat = 0 (0.00%) [20081217-09:46:56.160723347] writeall = 0 (0.00%) [20081217-09:46:56.162458713] writeall_fsync = 0 (0.00%) [20081217-09:46:56.164357088] open_close = 0 (0.00%) [20081217-09:46:56.166135099] write_fsync = 0 (0.00%) [20081217-09:46:56.168002120] create_fsync = 0 (0.00%) [20081217-09:46:56.169750120] append_fsync = 0 (0.00%) [20081217-09:46:56.171595954] [20081217-09:46:56.173373182] FileSystem /mnt/ffsb1 [20081217-09:46:56.175186161] ========== [20081217-09:46:56.176976047] num_dirs = 0 [20081217-09:46:56.179072861] starting files = 1024 [20081217-09:46:56.181181801] [20081217-09:46:56.183408337] min file size = 36700160 (35MB) [20081217-09:46:56.185292013] max file size = 36700160 (35MB) [20081217-09:46:56.187151996] directio = off [20081217-09:46:56.188941382] alignedio = on [20081217-09:46:56.190791566] bufferedio = off [20081217-09:46:56.192562957] [20081217-09:46:56.194376971] aging is off [20081217-09:46:56.196137814] current utilization = 55.72% [20081217-09:46:56.197960372] [20081217-09:46:56.199704889] checking existing fs: /mnt/ffsb1 [20081217-09:47:22.700499046] fs setup took 26 secs [20081217-09:47:23.159050377] Syncing()...0 sec [20081217-09:47:23.161340459] Starting Actual Benchmark At: Wed Dec 17 09:47:23 2008 [20081217-09:47:23.175000592] [20081217-09:52:56.092848535] Syncing()...24 sec [20081217-09:52:56.100288318] FFSB benchmark finished at: Wed Dec 17 09:52:56 2008 [20081217-09:52:56.102539927] [20081217-09:52:56.105248701] Results: [20081217-09:52:56.124828451] Benchmark took 332.93 sec [20081217-09:52:56.127277546] [20081217-09:52:56.129789596] Total Results [20081217-09:52:56.145109692] =============== [20081217-09:52:56.147865882] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-09:52:56.150659077] ======= ============ ========= ======= =========== ========== [20081217-09:52:56.153046347] write : 315136 946.54 100.000% 100.000% 129MB/sec [20081217-09:52:56.155658280] - [20081217-09:52:56.158224663] 946.54 Transactions per Second [20081217-09:52:56.160544789] [20081217-09:52:56.162993959] Throughput Results [20081217-09:52:56.177800607] =================== [20081217-09:52:56.180629358] Write Throughput: 129MB/sec [20081217-09:52:56.183603252] [20081217-09:52:56.186156262] System Call Latency statistics in millisecs [20081217-09:52:56.188868270] ===== [20081217-09:52:56.192101927] Min Avg Max Total Calls [20081217-09:52:56.194627874] ======== ======== ======== ============ [20081217-09:52:56.197242887] [ open] 0.010000 0.054433 6.938000 1231 [20081217-09:52:56.199959838] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:52:56.202675753] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:52:56.205322495] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:52:56.207926730] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-09:52:56.210883166] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-09:52:56.213657431] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-09:52:56.216185744] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-09:52:56.218747366] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-09:52:56.221245424] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-09:52:56.223822127] msec_range[9] 5.000000 - 10.000000 : 3 [20081217-09:52:56.226455778] msec_range[10] 2.000000 - 5.000000 : 4 [20081217-09:52:56.230518064] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-09:52:56.234006154] msec_range[12] 0.500000 - 1.000000 : 1 [20081217-09:52:56.237275383] msec_range[13] 0.200000 - 0.500000 : 2 [20081217-09:52:56.240207152] msec_range[14] 0.100000 - 0.200000 : 38 [20081217-09:52:56.242830066] msec_range[15] 0.050000 - 0.100000 : 77 [20081217-09:52:56.245443613] msec_range[16] 0.020000 - 0.050000 : 801 [20081217-09:52:56.247942771] msec_range[17] 0.010000 - 0.020000 : 305 [20081217-09:52:56.250520220] msec_range[18] 0.000000 - 0.010000 : 0 [20081217-09:52:56.254237192] [20081217-09:52:56.257670566] [ write] 0.009000 7.514057 58665.726562 315136 [20081217-09:52:56.260485297] msec_range[0] 5000.000000 - 10000.000000 : 60 [20081217-09:52:56.265503823] msec_range[1] 2000.000000 - 5000.000000 : 74 [20081217-09:52:56.268010297] msec_range[2] 1000.000000 - 2000.000000 : 80 [20081217-09:52:56.270467210] msec_range[3] 500.000000 - 1000.000000 : 147 [20081217-09:52:56.272693323] msec_range[4] 200.000000 - 500.000000 : 182 [20081217-09:52:56.275368994] msec_range[5] 100.000000 - 200.000000 : 159 [20081217-09:52:56.277741498] msec_range[6] 50.000000 - 100.000000 : 215 [20081217-09:52:56.282104521] msec_range[7] 20.000000 - 50.000000 : 699 [20081217-09:52:56.285185142] msec_range[8] 10.000000 - 20.000000 : 1853 [20081217-09:52:56.287758781] msec_range[9] 5.000000 - 10.000000 : 6110 [20081217-09:52:56.292525224] msec_range[10] 2.000000 - 5.000000 : 21867 [20081217-09:52:56.295362134] msec_range[11] 1.000000 - 2.000000 : 53382 [20081217-09:52:56.298245953] msec_range[12] 0.500000 - 1.000000 : 41762 [20081217-09:52:56.300882853] msec_range[13] 0.200000 - 0.500000 : 29198 [20081217-09:52:56.303604640] msec_range[14] 0.100000 - 0.200000 : 30466 [20081217-09:52:56.306379727] msec_range[15] 0.050000 - 0.100000 : 32254 [20081217-09:52:56.309142929] msec_range[16] 0.020000 - 0.050000 : 70273 [20081217-09:52:56.311708790] msec_range[17] 0.010000 - 0.020000 : 26308 [20081217-09:52:56.314859314] msec_range[18] 0.000000 - 0.010000 : 1 [20081217-09:52:56.317734377] [20081217-09:52:56.322814727] [ lseek] 0.000000 0.152582 9930.038086 315136 [20081217-09:52:56.325373262] msec_range[0] 5000.000000 - 10000.000000 : 4 [20081217-09:52:56.327779881] msec_range[1] 2000.000000 - 5000.000000 : 3 [20081217-09:52:56.330905645] msec_range[2] 1000.000000 - 2000.000000 : 1 [20081217-09:52:56.333993508] msec_range[3] 500.000000 - 1000.000000 : 1 [20081217-09:52:56.336855223] msec_range[4] 200.000000 - 500.000000 : 1 [20081217-09:52:56.340110891] msec_range[5] 100.000000 - 200.000000 : 2 [20081217-09:52:56.344389088] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-09:52:56.347035008] msec_range[7] 20.000000 - 50.000000 : 1 [20081217-09:52:56.349598510] msec_range[8] 10.000000 - 20.000000 : 4 [20081217-09:52:56.352734963] msec_range[9] 5.000000 - 10.000000 : 6 [20081217-09:52:56.355282266] msec_range[10] 2.000000 - 5.000000 : 58 [20081217-09:52:56.358178666] msec_range[11] 1.000000 - 2.000000 : 214 [20081217-09:52:56.360791121] msec_range[12] 0.500000 - 1.000000 : 311 [20081217-09:52:56.363625891] msec_range[13] 0.200000 - 0.500000 : 148 [20081217-09:52:56.366336817] msec_range[14] 0.100000 - 0.200000 : 94 [20081217-09:52:56.369023214] msec_range[15] 0.050000 - 0.100000 : 76 [20081217-09:52:56.371642348] msec_range[16] 0.020000 - 0.050000 : 169 [20081217-09:52:56.374252429] msec_range[17] 0.010000 - 0.020000 : 803 [20081217-09:52:56.376464669] msec_range[18] 0.000000 - 0.010000 : 313240 [20081217-09:52:56.378872418] [20081217-09:52:56.381378515] [ close] 0.003000 0.007446 0.604000 1231 [20081217-09:52:56.383844658] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:52:56.386203411] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:52:56.388401038] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:52:56.390792795] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-09:52:56.393152583] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-09:52:56.395410257] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-09:52:56.397770914] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-09:52:56.400110675] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-09:52:56.402268847] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-09:52:56.404478695] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-09:52:56.406696688] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-09:52:56.409120975] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-09:52:56.411706895] msec_range[12] 0.500000 - 1.000000 : 1 [20081217-09:52:56.414457897] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-09:52:56.416943407] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-09:52:56.419641228] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-09:52:56.422303872] msec_range[16] 0.020000 - 0.050000 : 4 [20081217-09:52:56.424603447] msec_range[17] 0.010000 - 0.020000 : 158 [20081217-09:52:56.426957024] msec_range[18] 0.000000 - 0.010000 : 1068 [20081217-09:52:56.432230291] [20081217-09:52:56.434657260] [20081217-09:52:56.437128529] [20081217-09:52:56.439894302] [20081217-09:52:56.442629662] 0.3% User Time [20081217-09:52:56.444964747] 27.1% System Time [20081217-09:52:56.447195311] 27.4% CPU Utilization [20081217-09:52:56.449731861] Profilers reporting [20081217-09:52:56.452214179] /autobench/scripts/doprofilers: line 33: 11821 Terminated ${CMDS[$i]} [20081217-09:52:56.454544036] /autobench/scripts/doprofilers: line 33: 11847 Terminated ${CMDS[$i]} [20081217-09:52:56.456893578] /autobench/scripts/doprofilers: line 33: 11882 Terminated ${CMDS[$i]} [20081217-09:53:16.114833728] Profilers postprocessing [20081217-09:53:16.395886616] Processing File : iostat.001 [20081217-09:53:16.398207297] Discovered iostat_interval=[5] [20081217-09:53:16.991561137] Processing Directory : sar.breakout.001 [20081217-09:53:16.993844538] Discovered sar_interval=[5] [20081217-09:53:17.164694692] Processing File : mpstat.001 [20081217-09:53:17.166935517] Discovered mpstat_interval=[5] [20081217-09:53:18.319400834] Stopping profiling. [20081217-09:53:18.324596050] Killing daemon. [20081217-09:53:19.545470605] Processing File : /autobench/logs/ffsb.random_writes__threads_0008.08-12-17_09.46.47/analysis/oprofile.001 [20081217-09:53:19.547755126] Processing File : /autobench/logs/ffsb.random_writes__threads_0008.08-12-17_09.46.47/analysis/oprofile-brief.001 [20081217-09:53:20.781640526] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-17_0900/btrfs-baseline' [20081217-09:53:22.892646781] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-09:53:26.910301072] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-09:53:28.204831534] PROCESSING COMMAND : 'run random_writes__threads_0032 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb num_threads=32' [20081217-09:53:28.248491605] new log requested [20081217-09:53:28.271273122] Running command ffsb [20081217-09:53:35.997341182] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb [20081217-09:53:36.010813209] Importing argument : num_threads=32 [20081217-09:53:36.037223485] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-09:53:36.102967253] FFSB version 6.0-RC2 started [20081217-09:53:36.105258587] [20081217-09:53:36.225798803] benchmark time = 300 [20081217-09:53:36.227920588] ThreadGroup 0 [20081217-09:53:36.230146868] ================ [20081217-09:53:36.232211153] num_threads = 32 [20081217-09:53:36.234432257] [20081217-09:53:36.236348121] read_random = off [20081217-09:53:36.238254099] read_size = 0 (0B) [20081217-09:53:36.240044913] read_blocksize = 0 (0B) [20081217-09:53:36.241894731] read_skip = off [20081217-09:53:36.243657166] read_skipsize = 0 (0B) [20081217-09:53:36.245554014] [20081217-09:53:36.247314617] write_random = on [20081217-09:53:36.249124901] write_size = 1048576 (1MB) [20081217-09:53:36.250877671] fsync_file = 0 [20081217-09:53:36.252719126] write_blocksize = 4096 (4KB) [20081217-09:53:36.254507403] wait time = 0 [20081217-09:53:36.256332165] [20081217-09:53:36.258067298] op weights [20081217-09:53:36.259909061] read = 0 (0.00%) [20081217-09:53:36.261693229] readall = 0 (0.00%) [20081217-09:53:36.263695487] write = 1 (100.00%) [20081217-09:53:36.265550179] create = 0 (0.00%) [20081217-09:53:36.267447800] append = 0 (0.00%) [20081217-09:53:36.269217259] delete = 0 (0.00%) [20081217-09:53:36.271068957] metaop = 0 (0.00%) [20081217-09:53:36.272853743] createdir = 0 (0.00%) [20081217-09:53:36.274684516] stat = 0 (0.00%) [20081217-09:53:36.276454491] writeall = 0 (0.00%) [20081217-09:53:36.278344501] writeall_fsync = 0 (0.00%) [20081217-09:53:36.280123064] open_close = 0 (0.00%) [20081217-09:53:36.281938463] write_fsync = 0 (0.00%) [20081217-09:53:36.283684810] create_fsync = 0 (0.00%) [20081217-09:53:36.285519496] append_fsync = 0 (0.00%) [20081217-09:53:36.287268440] [20081217-09:53:36.289059448] FileSystem /mnt/ffsb1 [20081217-09:53:36.290792312] ========== [20081217-09:53:36.292623419] num_dirs = 0 [20081217-09:53:36.294349647] starting files = 1024 [20081217-09:53:36.296159548] [20081217-09:53:36.297882859] min file size = 36700160 (35MB) [20081217-09:53:36.299699272] max file size = 36700160 (35MB) [20081217-09:53:36.301422592] directio = off [20081217-09:53:36.303223264] alignedio = on [20081217-09:53:36.304939177] bufferedio = off [20081217-09:53:36.306759346] [20081217-09:53:36.308472225] aging is off [20081217-09:53:36.310279768] current utilization = 57.45% [20081217-09:53:36.312009094] [20081217-09:53:36.313759913] checking existing fs: /mnt/ffsb1 [20081217-09:54:10.663406101] fs setup took 34 secs [20081217-09:54:11.309360747] Syncing()...0 sec [20081217-09:54:11.311739986] Starting Actual Benchmark At: Wed Dec 17 09:54:11 2008 [20081217-09:54:11.325082403] [20081217-10:00:03.780642106] Syncing()...37 sec [20081217-10:00:03.790514274] FFSB benchmark finished at: Wed Dec 17 10:00:03 2008 [20081217-10:00:03.793185681] [20081217-10:00:03.795741175] Results: [20081217-10:00:03.815435831] Benchmark took 352.47 sec [20081217-10:00:03.818028631] [20081217-10:00:03.820873995] Total Results [20081217-10:00:03.836271080] =============== [20081217-10:00:03.838914467] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-10:00:03.841375076] ======= ============ ========= ======= =========== ========== [20081217-10:00:03.844025249] write : 190976 541.82 100.000% 100.000% 74.1MB/sec [20081217-10:00:03.846871410] - [20081217-10:00:03.851282592] 541.82 Transactions per Second [20081217-10:00:03.854726891] [20081217-10:00:03.857949899] Throughput Results [20081217-10:00:03.873809274] =================== [20081217-10:00:03.877042476] Write Throughput: 74.1MB/sec [20081217-10:00:03.879866513] [20081217-10:00:03.883293078] System Call Latency statistics in millisecs [20081217-10:00:03.886275353] ===== [20081217-10:00:03.889026042] Min Avg Max Total Calls [20081217-10:00:03.891871836] ======== ======== ======== ============ [20081217-10:00:03.894921093] [ open] 0.008000 0.356402 217.326996 746 [20081217-10:00:03.898427561] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-10:00:03.901405280] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-10:00:03.905580308] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-10:00:03.908065488] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-10:00:03.910740076] msec_range[4] 200.000000 - 500.000000 : 1 [20081217-10:00:03.913062006] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-10:00:03.915431242] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-10:00:03.917665045] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-10:00:03.920357814] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-10:00:03.923333365] msec_range[9] 5.000000 - 10.000000 : 2 [20081217-10:00:03.926057302] msec_range[10] 2.000000 - 5.000000 : 3 [20081217-10:00:03.930598067] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-10:00:03.934478971] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-10:00:03.938337273] msec_range[13] 0.200000 - 0.500000 : 2 [20081217-10:00:03.941406668] msec_range[14] 0.100000 - 0.200000 : 12 [20081217-10:00:03.944015622] msec_range[15] 0.050000 - 0.100000 : 35 [20081217-10:00:03.946614567] msec_range[16] 0.020000 - 0.050000 : 573 [20081217-10:00:03.949126057] msec_range[17] 0.010000 - 0.020000 : 106 [20081217-10:00:03.952048452] msec_range[18] 0.000000 - 0.010000 : 12 [20081217-10:00:03.954759202] [20081217-10:00:03.957216483] [ write] 0.009000 49.113513 94142.820312 190976 [20081217-10:00:03.961115277] msec_range[0] 5000.000000 - 10000.000000 : 71 [20081217-10:00:03.963750088] msec_range[1] 2000.000000 - 5000.000000 : 209 [20081217-10:00:03.966096441] msec_range[2] 1000.000000 - 2000.000000 : 263 [20081217-10:00:03.968512464] msec_range[3] 500.000000 - 1000.000000 : 439 [20081217-10:00:03.972373398] msec_range[4] 200.000000 - 500.000000 : 524 [20081217-10:00:03.975133725] msec_range[5] 100.000000 - 200.000000 : 432 [20081217-10:00:03.977595359] msec_range[6] 50.000000 - 100.000000 : 464 [20081217-10:00:03.979870761] msec_range[7] 20.000000 - 50.000000 : 4089 [20081217-10:00:03.982701886] msec_range[8] 10.000000 - 20.000000 : 14259 [20081217-10:00:03.986000398] msec_range[9] 5.000000 - 10.000000 : 35156 [20081217-10:00:03.988668741] msec_range[10] 2.000000 - 5.000000 : 53000 [20081217-10:00:03.992796035] msec_range[11] 1.000000 - 2.000000 : 12718 [20081217-10:00:03.996563484] msec_range[12] 0.500000 - 1.000000 : 4948 [20081217-10:00:03.999598240] msec_range[13] 0.200000 - 0.500000 : 18768 [20081217-10:00:04.002070681] msec_range[14] 0.100000 - 0.200000 : 13561 [20081217-10:00:04.004245841] msec_range[15] 0.050000 - 0.100000 : 12546 [20081217-10:00:04.006904648] msec_range[16] 0.020000 - 0.050000 : 16754 [20081217-10:00:04.010028068] msec_range[17] 0.010000 - 0.020000 : 2552 [20081217-10:00:04.012969813] msec_range[18] 0.000000 - 0.010000 : 1 [20081217-10:00:04.015449903] [20081217-10:00:04.018359120] [ lseek] 0.000000 2.390465 94084.031250 190976 [20081217-10:00:04.021420145] msec_range[0] 5000.000000 - 10000.000000 : 5 [20081217-10:00:04.024947654] msec_range[1] 2000.000000 - 5000.000000 : 5 [20081217-10:00:04.028468534] msec_range[2] 1000.000000 - 2000.000000 : 1 [20081217-10:00:04.032660694] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-10:00:04.035348452] msec_range[4] 200.000000 - 500.000000 : 1 [20081217-10:00:04.039191176] msec_range[5] 100.000000 - 200.000000 : 2 [20081217-10:00:04.042900054] msec_range[6] 50.000000 - 100.000000 : 5 [20081217-10:00:04.045721331] msec_range[7] 20.000000 - 50.000000 : 23 [20081217-10:00:04.048355180] msec_range[8] 10.000000 - 20.000000 : 59 [20081217-10:00:04.051029534] msec_range[9] 5.000000 - 10.000000 : 121 [20081217-10:00:04.053456890] msec_range[10] 2.000000 - 5.000000 : 398 [20081217-10:00:04.056066649] msec_range[11] 1.000000 - 2.000000 : 260 [20081217-10:00:04.058719594] msec_range[12] 0.500000 - 1.000000 : 84 [20081217-10:00:04.061474129] msec_range[13] 0.200000 - 0.500000 : 59 [20081217-10:00:04.063993269] msec_range[14] 0.100000 - 0.200000 : 55 [20081217-10:00:04.066775056] msec_range[15] 0.050000 - 0.100000 : 66 [20081217-10:00:04.069262829] msec_range[16] 0.020000 - 0.050000 : 255 [20081217-10:00:04.071456763] msec_range[17] 0.010000 - 0.020000 : 1140 [20081217-10:00:04.073810186] msec_range[18] 0.000000 - 0.010000 : 188422 [20081217-10:00:04.076305717] [20081217-10:00:04.078823125] [ close] 0.002000 0.008276 0.039000 746 [20081217-10:00:04.082600833] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-10:00:04.085100951] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-10:00:04.087498161] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-10:00:04.090116641] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-10:00:04.092698729] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-10:00:04.095222373] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-10:00:04.097855580] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-10:00:04.100325642] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-10:00:04.102955962] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-10:00:04.105264170] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-10:00:04.107665559] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-10:00:04.109944097] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-10:00:04.112079591] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-10:00:04.114554341] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-10:00:04.116886029] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-10:00:04.120277824] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-10:00:04.122657075] msec_range[16] 0.020000 - 0.050000 : 7 [20081217-10:00:04.125170633] msec_range[17] 0.010000 - 0.020000 : 174 [20081217-10:00:04.127443425] msec_range[18] 0.000000 - 0.010000 : 565 [20081217-10:00:04.129615275] [20081217-10:00:04.131927541] [20081217-10:00:04.134090600] [20081217-10:00:04.136275673] [20081217-10:00:04.138494618] 0.2% User Time [20081217-10:00:04.140615947] 49.8% System Time [20081217-10:00:04.142794527] 50.0% CPU Utilization [20081217-10:00:04.144928544] Profilers reporting [20081217-10:00:04.147227493] /autobench/scripts/doprofilers: line 33: 17743 Terminated ${CMDS[$i]} [20081217-10:00:04.149463294] /autobench/scripts/doprofilers: line 33: 17760 Terminated ${CMDS[$i]} [20081217-10:00:04.151643951] /autobench/scripts/doprofilers: line 33: 17799 Terminated ${CMDS[$i]} [20081217-10:00:22.900045157] Profilers postprocessing [20081217-10:00:23.010748116] Processing File : iostat.001 [20081217-10:00:23.012967322] Discovered iostat_interval=[5] [20081217-10:00:23.626861651] Processing Directory : sar.breakout.001 [20081217-10:00:23.628971343] Discovered sar_interval=[5] [20081217-10:00:23.806551751] Processing File : mpstat.001 [20081217-10:00:23.808736304] Discovered mpstat_interval=[5] [20081217-10:00:24.954236867] Stopping profiling. [20081217-10:00:24.958744871] Killing daemon. [20081217-10:00:27.220449523] Processing File : /autobench/logs/ffsb.random_writes__threads_0032.08-12-17_09.53.28/analysis/oprofile.001 [20081217-10:00:27.222728171] Processing File : /autobench/logs/ffsb.random_writes__threads_0032.08-12-17_09.53.28/analysis/oprofile-brief.001 [20081217-10:00:28.628691359] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-17_0900/btrfs-baseline' [20081217-10:00:30.703184636] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-10:00:37.122931446] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-10:00:38.761923852] PROCESSING COMMAND : 'run random_writes_odirect__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes_odirect.ffsb num_threads=1' [20081217-10:00:38.806248404] new log requested [20081217-10:00:38.829454777] Running command ffsb [20081217-10:00:46.611212172] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes_odirect.ffsb [20081217-10:00:46.624236058] Importing argument : num_threads=1 [20081217-10:00:46.650309234] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-10:00:46.715737296] FFSB version 6.0-RC2 started [20081217-10:00:46.718046190] [20081217-10:00:46.720039390] benchmark time = 300 [20081217-10:00:46.722062053] ThreadGroup 0 [20081217-10:00:46.724058492] ================ [20081217-10:00:46.725946400] num_threads = 1 [20081217-10:00:46.727707581] [20081217-10:00:46.729535471] read_random = off [20081217-10:00:46.731318472] read_size = 0 (0B) [20081217-10:00:46.733182218] read_blocksize = 0 (0B) [20081217-10:00:46.734942995] read_skip = off [20081217-10:00:46.736768110] read_skipsize = 0 (0B) [20081217-10:00:46.738522368] [20081217-10:00:46.740270430] write_random = on [20081217-10:00:46.742053375] write_size = 1048576 (1MB) [20081217-10:00:46.743900384] fsync_file = 0 [20081217-10:00:46.745655202] write_blocksize = 4096 (4KB) [20081217-10:00:46.747460904] wait time = 0 [20081217-10:00:46.749198464] [20081217-10:00:46.751010344] op weights [20081217-10:00:46.752789218] read = 0 (0.00%) [20081217-10:00:46.754851409] readall = 0 (0.00%) [20081217-10:00:46.756561666] write = 1 (100.00%) [20081217-10:00:46.758312474] create = 0 (0.00%) [20081217-10:00:46.760144456] append = 0 (0.00%) [20081217-10:00:46.762000950] delete = 0 (0.00%) [20081217-10:00:46.763742494] metaop = 0 (0.00%) [20081217-10:00:46.765532642] createdir = 0 (0.00%) [20081217-10:00:46.767315455] stat = 0 (0.00%) [20081217-10:00:46.769118436] writeall = 0 (0.00%) [20081217-10:00:46.770867814] writeall_fsync = 0 (0.00%) [20081217-10:00:46.772680845] open_close = 0 (0.00%) [20081217-10:00:46.774431065] write_fsync = 0 (0.00%) [20081217-10:00:46.776183006] create_fsync = 0 (0.00%) [20081217-10:00:46.777941608] append_fsync = 0 (0.00%) [20081217-10:00:46.779750025] [20081217-10:00:46.781511129] FileSystem /mnt/ffsb1 [20081217-10:00:46.783352046] ========== [20081217-10:00:46.785144091] num_dirs = 0 [20081217-10:00:46.787223863] starting files = 1024 [20081217-10:00:46.789386328] [20081217-10:00:46.791616561] min file size = 36700160 (35MB) [20081217-10:00:46.793497688] max file size = 36700160 (35MB) [20081217-10:00:46.795396771] directio = on [20081217-10:00:46.797197876] alignedio = on [20081217-10:00:46.799038930] bufferedio = off [20081217-10:00:46.800823007] [20081217-10:00:46.802680160] aging is off [20081217-10:00:46.804444157] current utilization = 58.47% [20081217-10:00:46.806272304] [20081217-10:00:46.808020521] checking existing fs: /mnt/ffsb1 [20081217-10:01:23.999293816] fs setup took 37 secs [20081217-10:01:24.620028308] Syncing()...0 sec [20081217-10:01:24.622277040] Starting Actual Benchmark At: Wed Dec 17 10:01:24 2008 [20081217-10:01:24.635863738] [20081217-10:06:30.484958495] Syncing()...4 sec [20081217-10:06:30.487974723] FFSB benchmark finished at: Wed Dec 17 10:06:30 2008 [20081217-10:06:30.490744415] [20081217-10:06:30.493069036] Results: [20081217-10:06:30.508401837] Benchmark took 305.86 sec [20081217-10:06:30.510687911] [20081217-10:06:30.513260550] Total Results [20081217-10:06:30.528866619] =============== [20081217-10:06:30.531396949] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-10:06:30.534372006] ======= ============ ========= ======= =========== ========== [20081217-10:06:30.537832138] write : 23552 77.00 100.000% 100.000% 10.5MB/sec [20081217-10:06:30.540631502] - [20081217-10:06:30.543347968] 77.00 Transactions per Second [20081217-10:06:30.545675712] [20081217-10:06:30.548816317] Throughput Results [20081217-10:06:30.565881729] =================== [20081217-10:06:30.568739721] Write Throughput: 10.5MB/sec [20081217-10:06:30.571320959] [20081217-10:06:30.573607788] System Call Latency statistics in millisecs [20081217-10:06:30.577217278] ===== [20081217-10:06:30.585318876] Min Avg Max Total Calls [20081217-10:06:30.588886616] ======== ======== ======== ============ [20081217-10:06:30.591615444] [ open] 0.012000 0.023761 0.110000 92 [20081217-10:06:30.594346421] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-10:06:30.596961329] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-10:06:30.599322064] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-10:06:30.601516588] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-10:06:30.603615831] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-10:06:30.607175719] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-10:06:30.609838765] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-10:06:30.612631474] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-10:06:30.618182686] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-10:06:30.621027449] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-10:06:30.623938010] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-10:06:30.626404098] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-10:06:30.628697831] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-10:06:30.631258003] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-10:06:30.633536643] msec_range[14] 0.100000 - 0.200000 : 1 [20081217-10:06:30.635711724] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-10:06:30.638042372] msec_range[16] 0.020000 - 0.050000 : 67 [20081217-10:06:30.640311705] msec_range[17] 0.010000 - 0.020000 : 24 [20081217-10:06:30.642447880] msec_range[18] 0.000000 - 0.010000 : 0 [20081217-10:06:30.644894901] [20081217-10:06:30.648724529] [ write] 2.043000 12.810528 19570.671875 23552 [20081217-10:06:30.653003442] msec_range[0] 5000.000000 - 10000.000000 : 1 [20081217-10:06:30.656537498] msec_range[1] 2000.000000 - 5000.000000 : 7 [20081217-10:06:30.659094641] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-10:06:30.662850936] msec_range[3] 500.000000 - 1000.000000 : 3 [20081217-10:06:30.665243799] msec_range[4] 200.000000 - 500.000000 : 22 [20081217-10:06:30.668104729] msec_range[5] 100.000000 - 200.000000 : 42 [20081217-10:06:30.670350397] msec_range[6] 50.000000 - 100.000000 : 148 [20081217-10:06:30.673121225] msec_range[7] 20.000000 - 50.000000 : 987 [20081217-10:06:30.675543182] msec_range[8] 10.000000 - 20.000000 : 2720 [20081217-10:06:30.677657563] msec_range[9] 5.000000 - 10.000000 : 12008 [20081217-10:06:30.681063774] msec_range[10] 2.000000 - 5.000000 : 7610 [20081217-10:06:30.684044050] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-10:06:30.686786064] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-10:06:30.689645774] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-10:06:30.693199361] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-10:06:30.695629062] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-10:06:30.697677924] msec_range[16] 0.020000 - 0.050000 : 0 [20081217-10:06:30.699729597] msec_range[17] 0.010000 - 0.020000 : 0 [20081217-10:06:30.701766523] msec_range[18] 0.000000 - 0.010000 : 0 [20081217-10:06:30.704082063] [20081217-10:06:30.708321525] [ lseek] 0.000000 0.001322 0.023000 23552 [20081217-10:06:30.711379798] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-10:06:30.714976980] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-10:06:30.718380775] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-10:06:30.720911582] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-10:06:30.724165568] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-10:06:30.727022505] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-10:06:30.729794636] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-10:06:30.732704614] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-10:06:30.735328842] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-10:06:30.739725702] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-10:06:30.743115582] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-10:06:30.746147473] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-10:06:30.748993583] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-10:06:30.751497579] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-10:06:30.753842519] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-10:06:30.757050991] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-10:06:30.760051336] msec_range[16] 0.020000 - 0.050000 : 2 [20081217-10:06:30.762988437] msec_range[17] 0.010000 - 0.020000 : 11 [20081217-10:06:30.766015379] msec_range[18] 0.000000 - 0.010000 : 23539 [20081217-10:06:30.768644021] [20081217-10:06:30.771187781] [ close] 0.003000 0.005957 0.011000 92 [20081217-10:06:30.773761921] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-10:06:30.776438312] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-10:06:30.778957641] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-10:06:30.781632614] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-10:06:30.784071332] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-10:06:30.786414046] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-10:06:30.789060245] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-10:06:30.791552727] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-10:06:30.794251601] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-10:06:30.796668709] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-10:06:30.799258663] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-10:06:30.801740367] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-10:06:30.804360844] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-10:06:30.807012547] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-10:06:30.809409187] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-10:06:30.811876576] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-10:06:30.814280447] msec_range[16] 0.020000 - 0.050000 : 0 [20081217-10:06:30.816716689] msec_range[17] 0.010000 - 0.020000 : 7 [20081217-10:06:30.819097969] msec_range[18] 0.000000 - 0.010000 : 85 [20081217-10:06:30.821380989] [20081217-10:06:30.823599620] [20081217-10:06:30.825745352] [20081217-10:06:30.827985964] [20081217-10:06:30.830187931] 0.0% User Time [20081217-10:06:30.832320453] 1.9% System Time [20081217-10:06:30.834529899] 1.9% CPU Utilization [20081217-10:06:30.836722400] Profilers reporting [20081217-10:06:30.838850566] /autobench/scripts/doprofilers: line 33: 23739 Terminated ${CMDS[$i]} [20081217-10:06:43.973826786] Profilers postprocessing [20081217-10:06:44.062096002] Processing File : iostat.001 [20081217-10:06:44.064416650] Discovered iostat_interval=[5] [20081217-10:06:44.599115650] Processing Directory : sar.breakout.001 [20081217-10:06:44.601406091] Discovered sar_interval=[5] [20081217-10:06:44.764321824] Processing File : mpstat.001 [20081217-10:06:44.766634810] Discovered mpstat_interval=[5] [20081217-10:06:45.899459989] Stopping profiling. [20081217-10:06:45.904245899] Killing daemon. [20081217-10:06:47.077975910] Processing File : /autobench/logs/ffsb.random_writes_odirect__threads_0001.08-12-17_10.00.38/analysis/oprofile.001 [20081217-10:06:47.080207181] Processing File : /autobench/logs/ffsb.random_writes_odirect__threads_0001.08-12-17_10.00.38/analysis/oprofile-brief.001 [20081217-10:06:48.093177255] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-17_0900/btrfs-baseline'