[20090728-08:51:38.358153859] PROCESSING COMMAND : 'clearprofilers' [20090728-08:51:38.649665892] PROCESSING COMMAND : 'useprofiler iostat 5' [20090728-08:51:38.769211181] Checking for sar... [20090728-08:51:38.774089809] found [20090728-08:51:38.922261883] PROCESSING COMMAND : 'useprofiler sar 5' [20090728-08:51:39.042224456] Checking for sar... [20090728-08:51:39.044510494] found [20090728-08:51:39.195650684] PROCESSING COMMAND : 'useprofiler mpstat 5' [20090728-08:51:39.316092060] Checking for sar... [20090728-08:51:39.318427598] found [20090728-08:51:39.583655044] PROCESSING COMMAND : 'umount /mnt/ffsb1 > /dev/null 2>&1' [20090728-08:51:39.664347738] PROCESSING COMMAND : 'set-sched noop' [20090728-08:51:39.990586239] PROCESSING COMMAND : 'mkresultdirs hks.austin.ibm.com benchmarks/results/btrfs/ffsb btrfs1 2009-07-28_0851 btrfsexp-7-24' [20090728-08:51:40.254442616] Connecting to hks.austin.ibm.com... [20090728-08:51:40.256852889] Remote working directory: /opt [20090728-08:51:40.260487724] Remote working directory: /opt/benchmarks/results/btrfs/ffsb [20090728-08:51:40.262823666] Couldn't create directory: Failure [20090728-08:51:40.265175756] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1 [20090728-08:51:40.267144536] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs1 [20090728-08:51:40.269577195] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1/2009-07-28_0851 [20090728-08:51:40.271798543] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs1/2009-07-28_0851 [20090728-08:51:40.274035295] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1/2009-07-28_0851/btrfsexp-7-24 [20090728-08:51:40.335460225] ONLY : Command [mkfs.btrfs 2>&1] found for me [20090728-08:51:40.388982071] PROCESSING COMMAND : 'mkfs.btrfs 2>&1' [20090728-08:51:40.419465547] usage: mkfs.btrfs [options] dev [ dev ... ] [20090728-08:51:40.421797391] options: [20090728-08:51:40.423929848] -A --alloc-start the offset to start the FS [20090728-08:51:40.426148851] -b --byte-count total number of bytes in the FS [20090728-08:51:40.428326765] -d --data data profile, raid0, raid1, raid10 or single [20090728-08:51:40.430381434] -l --leafsize size of btree leaves [20090728-08:51:40.432660659] -L --label set a label [20090728-08:51:40.434835960] -m --metadata metadata profile, values like data profile [20090728-08:51:40.436970524] -n --nodesize size of btree nodes [20090728-08:51:40.439130420] -s --sectorsize min block allocation [20090728-08:51:40.441198240] Btrfs v0.18-13-gb8420fa [20090728-08:51:40.523153387] PROCESSING COMMAND : 'mkfs.btrfs /dev/ffsbdev1' [20090728-08:51:40.567132534] [20090728-08:51:40.569517130] WARNING! - Btrfs v0.18-13-gb8420fa IS EXPERIMENTAL [20090728-08:51:40.571887158] WARNING! - see http://btrfs.wiki.kernel.org before using [20090728-08:51:40.574209805] [20090728-08:51:40.576554693] fs created label (null) on /dev/ffsbdev1 [20090728-08:51:40.578980628] nodesize 4096 leafsize 4096 sectorsize 4096 size 2.18TB [20090728-08:51:40.580994284] Btrfs v0.18-13-gb8420fa [20090728-08:51:40.753852219] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090728-08:51:40.837291543] ONLY : Command [run sequential_reads__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb reuse=1 num_threads=1] found for me [20090728-08:51:40.891383288] PROCESSING COMMAND : 'run sequential_reads__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb reuse=1 num_threads=1' [20090728-08:51:40.939083049] new log requested [20090728-08:51:40.970670321] Running command ffsb [20090728-08:51:51.823061478] 07/28/2009-08:51:51 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb Succeeded [20090728-08:51:51.834292913] Importing argument : reuse=1 [20090728-08:51:51.847879424] Importing argument : num_threads=1 [20090728-08:51:51.877534638] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090728-08:51:51.964232376] FFSB version 6.0-RC2.1 started [20090728-08:51:51.966566206] [20090728-08:51:51.971017502] benchmark time = 300 [20090728-08:51:51.973045280] ThreadGroup 0 [20090728-08:51:51.975221131] ================ [20090728-08:51:51.977172352] num_threads = 1 [20090728-08:51:51.979296919] [20090728-08:51:51.981443424] read_random = off [20090728-08:51:51.983757936] read_size = 0 (0B) [20090728-08:51:51.986079365] read_blocksize = 4096 (4KB) [20090728-08:51:51.988273159] read_skip = off [20090728-08:51:51.990318220] read_skipsize = 0 (0B) [20090728-08:51:51.992292690] [20090728-08:51:51.994358330] write_random = off [20090728-08:51:51.996340655] write_size = 0 (0B) [20090728-08:51:51.998380354] fsync_file = 0 [20090728-08:51:52.000342408] write_blocksize = 0 (0B) [20090728-08:51:52.002445379] wait time = 0 [20090728-08:51:52.004580708] [20090728-08:51:52.006579099] op weights [20090728-08:51:52.008691503] read = 0 (0.00%) [20090728-08:51:52.010585470] readall = 1 (100.00%) [20090728-08:51:52.012713018] write = 0 (0.00%) [20090728-08:51:52.014845054] create = 0 (0.00%) [20090728-08:51:52.016803822] append = 0 (0.00%) [20090728-08:51:52.018864467] delete = 0 (0.00%) [20090728-08:51:52.020943147] metaop = 0 (0.00%) [20090728-08:51:52.022815817] createdir = 0 (0.00%) [20090728-08:51:52.024978036] stat = 0 (0.00%) [20090728-08:51:52.027025980] writeall = 0 (0.00%) [20090728-08:51:52.028941659] writeall_fsync = 0 (0.00%) [20090728-08:51:52.030989422] open_close = 0 (0.00%) [20090728-08:51:52.033030706] write_fsync = 0 (0.00%) [20090728-08:51:52.034934328] create_fsync = 0 (0.00%) [20090728-08:51:52.036955285] append_fsync = 0 (0.00%) [20090728-08:51:52.039045968] [20090728-08:51:52.040957813] FileSystem /mnt/ffsb1 [20090728-08:51:52.043219233] ========== [20090728-08:51:52.045274898] num_dirs = 0 [20090728-08:51:52.047340468] starting files = 1024 [20090728-08:51:52.049445565] [20090728-08:51:52.051427712] min file size = 104857600 (100MB) [20090728-08:51:52.053485929] max file size = 104857600 (100MB) [20090728-08:51:52.055452250] directio = off [20090728-08:51:52.057443394] alignedio = on [20090728-08:51:52.059369157] bufferedio = off [20090728-08:51:52.061453981] [20090728-08:51:52.063476093] aging is off [20090728-08:51:52.065435990] current utilization = 0.00% [20090728-08:51:52.067463305] [20090728-08:51:52.069422303] checking existing fs: /mnt/ffsb1 [20090728-08:51:52.071404267] opendir: No such file or directory [20090728-08:51:52.073332644] recreating new fileset [20090728-08:57:23.159780791] fs setup took 330 secs [20090728-08:57:24.352166288] Syncing()...1 sec [20090728-08:57:24.355168378] Starting Actual Benchmark At: Tue Jul 28 08:57:24 2009 [20090728-08:57:24.467582126] [20090728-09:02:25.573120762] Syncing()...0 sec [20090728-09:02:25.616040876] FFSB benchmark finished at: Tue Jul 28 09:02:25 2009 [20090728-09:02:25.618659907] [20090728-09:02:25.621233784] Results: [20090728-09:02:25.663787579] Benchmark took 300.95 sec [20090728-09:02:25.667038234] [20090728-09:02:25.669438358] Total Results [20090728-09:02:25.684926954] =============== [20090728-09:02:25.686952436] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090728-09:02:25.689110192] ======= ============ ========= ======= =========== ========== [20090728-09:02:25.691277848] readall : 20966400 69668.10 100.000% 100.000% 272MB/sec [20090728-09:02:25.693325924] - [20090728-09:02:25.695344648] 69668.10 Transactions per Second [20090728-09:02:25.697416238] [20090728-09:02:25.700167357] Throughput Results [20090728-09:02:25.714929229] =================== [20090728-09:02:25.717133189] Read Throughput: 272MB/sec [20090728-09:02:25.719375481] [20090728-09:02:25.721772534] System Call Latency statistics in millisecs [20090728-09:02:25.723877544] ===== [20090728-09:02:25.726681349] Min Avg Max Total Calls [20090728-09:02:25.728882759] ======== ======== ======== ============ [20090728-09:02:25.731005002] [ open] 0.015000 0.737319 13.027000 819 [20090728-09:02:25.733048277] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-09:02:25.735798642] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-09:02:25.737723170] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-09:02:25.739680193] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-09:02:25.741588601] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-09:02:25.743963181] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-09:02:25.746003363] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-09:02:25.747970379] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-09:02:25.750058956] msec_range[8] 10.000000 - 20.000000 : 4 [20090728-09:02:25.752046000] msec_range[9] 5.000000 - 10.000000 : 42 [20090728-09:02:25.754112215] msec_range[10] 2.000000 - 5.000000 : 70 [20090728-09:02:25.756013177] msec_range[11] 1.000000 - 2.000000 : 0 [20090728-09:02:25.757994573] msec_range[12] 0.500000 - 1.000000 : 17 [20090728-09:02:25.759956470] msec_range[13] 0.200000 - 0.500000 : 0 [20090728-09:02:25.761965126] msec_range[14] 0.100000 - 0.200000 : 1 [20090728-09:02:25.763890347] msec_range[15] 0.050000 - 0.100000 : 77 [20090728-09:02:25.766100827] msec_range[16] 0.020000 - 0.050000 : 603 [20090728-09:02:25.768063797] msec_range[17] 0.010000 - 0.020000 : 5 [20090728-09:02:25.769977987] msec_range[18] 0.000000 - 0.010000 : 0 [20090728-09:02:25.771926440] [20090728-09:02:25.774574658] [ read] 0.001000 0.014093 105.486000 20966400 [20090728-09:02:25.776638700] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-09:02:25.778573277] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-09:02:25.780615593] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-09:02:25.782649540] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-09:02:25.784707305] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-09:02:25.786599648] msec_range[5] 100.000000 - 200.000000 : 2 [20090728-09:02:25.788583995] msec_range[6] 50.000000 - 100.000000 : 2 [20090728-09:02:25.790502735] msec_range[7] 20.000000 - 50.000000 : 433 [20090728-09:02:25.792489781] msec_range[8] 10.000000 - 20.000000 : 2531 [20090728-09:02:25.794392227] msec_range[9] 5.000000 - 10.000000 : 13245 [20090728-09:02:25.796392183] msec_range[10] 2.000000 - 5.000000 : 9794 [20090728-09:02:25.798323328] msec_range[11] 1.000000 - 2.000000 : 2884 [20090728-09:02:25.800286561] msec_range[12] 0.500000 - 1.000000 : 2421 [20090728-09:02:25.802180805] msec_range[13] 0.200000 - 0.500000 : 4990 [20090728-09:02:25.804067918] msec_range[14] 0.100000 - 0.200000 : 6596 [20090728-09:02:25.806049961] msec_range[15] 0.050000 - 0.100000 : 11040 [20090728-09:02:25.808020194] msec_range[16] 0.020000 - 0.050000 : 8336 [20090728-09:02:25.809883404] msec_range[17] 0.010000 - 0.020000 : 77235 [20090728-09:02:25.811838422] msec_range[18] 0.000000 - 0.010000 : 20826891 [20090728-09:02:25.813783861] [20090728-09:02:25.815774532] [ close] 0.003000 0.007150 0.014000 819 [20090728-09:02:25.817706504] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-09:02:25.819877167] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-09:02:25.822082936] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-09:02:25.824481755] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-09:02:25.827235766] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-09:02:25.829532347] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-09:02:25.831971708] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-09:02:25.834067569] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-09:02:25.836670003] msec_range[8] 10.000000 - 20.000000 : 0 [20090728-09:02:25.838725748] msec_range[9] 5.000000 - 10.000000 : 0 [20090728-09:02:25.840792812] msec_range[10] 2.000000 - 5.000000 : 0 [20090728-09:02:25.843565082] msec_range[11] 1.000000 - 2.000000 : 0 [20090728-09:02:25.846053930] msec_range[12] 0.500000 - 1.000000 : 0 [20090728-09:02:25.848395571] msec_range[13] 0.200000 - 0.500000 : 0 [20090728-09:02:25.850650748] msec_range[14] 0.100000 - 0.200000 : 0 [20090728-09:02:25.852912139] msec_range[15] 0.050000 - 0.100000 : 0 [20090728-09:02:25.854955547] msec_range[16] 0.020000 - 0.050000 : 0 [20090728-09:02:25.856905968] msec_range[17] 0.010000 - 0.020000 : 10 [20090728-09:02:25.858950514] msec_range[18] 0.000000 - 0.010000 : 809 [20090728-09:02:25.861013418] [20090728-09:02:25.863143601] [20090728-09:02:25.865065799] [20090728-09:02:25.867058141] [20090728-09:02:25.869060523] 3.4% User Time [20090728-09:02:25.870987246] 71.6% System Time [20090728-09:02:25.873003450] 75.0% CPU Utilization [20090728-09:02:25.938324699] Profilers reporting [20090728-09:02:26.280017255] Profilers postprocessing [20090728-09:02:26.584773372] Processing File : iostat.001 [20090728-09:02:26.587515898] Discovered iostat_interval=[5] [20090728-09:02:27.372912296] Processing Directory : sar.breakout.001 [20090728-09:02:27.375378337] Discovered sar_interval=[5] [20090728-09:02:27.555990934] Processing File : mpstat.001 [20090728-09:02:27.558299846] Discovered mpstat_interval=[5] [20090728-09:02:29.197190905] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-07-28_0851/btrfsexp-7-24' [20090728-09:02:35.142631473] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090728-09:02:37.459861542] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090728-09:02:37.787886234] ONLY : Command [run sequential_reads__threads_0016 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb reuse=1 num_threads=16] found for me [20090728-09:02:37.841439675] PROCESSING COMMAND : 'run sequential_reads__threads_0016 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb reuse=1 num_threads=16' [20090728-09:02:37.890629227] new log requested [20090728-09:02:37.932771205] Running command ffsb [20090728-09:02:49.037918251] 07/28/2009-09:02:49 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb Succeeded [20090728-09:02:49.049228434] Importing argument : reuse=1 [20090728-09:02:49.063023515] Importing argument : num_threads=16 [20090728-09:02:49.090525012] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090728-09:02:49.173799127] FFSB version 6.0-RC2.1 started [20090728-09:02:49.176160627] [20090728-09:02:49.241105330] benchmark time = 300 [20090728-09:02:49.242951622] ThreadGroup 0 [20090728-09:02:49.245174998] ================ [20090728-09:02:49.247141981] num_threads = 16 [20090728-09:02:49.249313394] [20090728-09:02:49.251531752] read_random = off [20090728-09:02:49.253891561] read_size = 0 (0B) [20090728-09:02:49.255893092] read_blocksize = 4096 (4KB) [20090728-09:02:49.257812393] read_skip = off [20090728-09:02:49.259949972] read_skipsize = 0 (0B) [20090728-09:02:49.262090264] [20090728-09:02:49.264037865] write_random = off [20090728-09:02:49.266064153] write_size = 0 (0B) [20090728-09:02:49.268067923] fsync_file = 0 [20090728-09:02:49.270098176] write_blocksize = 0 (0B) [20090728-09:02:49.272083979] wait time = 0 [20090728-09:02:49.274060761] [20090728-09:02:49.275988791] op weights [20090728-09:02:49.277941360] read = 0 (0.00%) [20090728-09:02:49.279878277] readall = 1 (100.00%) [20090728-09:02:49.281854392] write = 0 (0.00%) [20090728-09:02:49.283777820] create = 0 (0.00%) [20090728-09:02:49.285748041] append = 0 (0.00%) [20090728-09:02:49.287861855] delete = 0 (0.00%) [20090728-09:02:49.289923032] metaop = 0 (0.00%) [20090728-09:02:49.292015329] createdir = 0 (0.00%) [20090728-09:02:49.293973098] stat = 0 (0.00%) [20090728-09:02:49.296025187] writeall = 0 (0.00%) [20090728-09:02:49.297969511] writeall_fsync = 0 (0.00%) [20090728-09:02:49.299998739] open_close = 0 (0.00%) [20090728-09:02:49.301924827] write_fsync = 0 (0.00%) [20090728-09:02:49.303891130] create_fsync = 0 (0.00%) [20090728-09:02:49.305793699] append_fsync = 0 (0.00%) [20090728-09:02:49.307798815] [20090728-09:02:49.309780393] FileSystem /mnt/ffsb1 [20090728-09:02:49.311717221] ========== [20090728-09:02:49.313733383] num_dirs = 0 [20090728-09:02:49.315669501] starting files = 1024 [20090728-09:02:49.317610521] [20090728-09:02:49.319519103] min file size = 104857600 (100MB) [20090728-09:02:49.321542789] max file size = 104857600 (100MB) [20090728-09:02:49.323378145] directio = off [20090728-09:02:49.325318778] alignedio = on [20090728-09:02:49.328110802] bufferedio = off [20090728-09:02:49.330128927] [20090728-09:02:49.332041756] aging is off [20090728-09:02:49.334014381] current utilization = 4.48% [20090728-09:02:49.335939225] [20090728-09:02:49.337937608] checking existing fs: /mnt/ffsb1 [20090728-09:02:49.553689517] fs setup took 0 secs [20090728-09:02:50.433129904] Syncing()...0 sec [20090728-09:02:50.435655104] Starting Actual Benchmark At: Tue Jul 28 09:02:50 2009 [20090728-09:02:50.450930693] [20090728-09:07:53.782357233] Syncing()...0 sec [20090728-09:07:53.844036352] FFSB benchmark finished at: Tue Jul 28 09:07:53 2009 [20090728-09:07:53.846677066] [20090728-09:07:53.849192980] Results: [20090728-09:07:53.891736790] Benchmark took 302.96 sec [20090728-09:07:53.894242158] [20090728-09:07:53.896635317] Total Results [20090728-09:07:53.911941377] =============== [20090728-09:07:53.914301512] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090728-09:07:53.916498896] ======= ============ ========= ======= =========== ========== [20090728-09:07:53.918870563] readall : 39168000 129286.34 100.000% 100.000% 505MB/sec [20090728-09:07:53.921236423] - [20090728-09:07:53.923368312] 129286.34 Transactions per Second [20090728-09:07:53.925506638] [20090728-09:07:53.927421221] Throughput Results [20090728-09:07:53.942141294] =================== [20090728-09:07:53.944306781] Read Throughput: 505MB/sec [20090728-09:07:53.946485358] [20090728-09:07:53.948449611] System Call Latency statistics in millisecs [20090728-09:07:53.950541081] ===== [20090728-09:07:53.952523415] Min Avg Max Total Calls [20090728-09:07:53.954724667] ======== ======== ======== ============ [20090728-09:07:53.956716500] [ open] 0.007000 12.561875 1629.792969 1530 [20090728-09:07:53.958772266] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-09:07:53.960741312] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-09:07:53.962723236] msec_range[2] 1000.000000 - 2000.000000 : 2 [20090728-09:07:53.964641984] msec_range[3] 500.000000 - 1000.000000 : 10 [20090728-09:07:53.966655838] msec_range[4] 200.000000 - 500.000000 : 11 [20090728-09:07:53.968753832] msec_range[5] 100.000000 - 200.000000 : 5 [20090728-09:07:53.970875847] msec_range[6] 50.000000 - 100.000000 : 17 [20090728-09:07:53.973095045] msec_range[7] 20.000000 - 50.000000 : 33 [20090728-09:07:53.975139498] msec_range[8] 10.000000 - 20.000000 : 66 [20090728-09:07:53.977141001] msec_range[9] 5.000000 - 10.000000 : 80 [20090728-09:07:53.979119991] msec_range[10] 2.000000 - 5.000000 : 44 [20090728-09:07:53.981157936] msec_range[11] 1.000000 - 2.000000 : 2 [20090728-09:07:53.983131796] msec_range[12] 0.500000 - 1.000000 : 1 [20090728-09:07:53.985056882] msec_range[13] 0.200000 - 0.500000 : 1 [20090728-09:07:53.987013974] msec_range[14] 0.100000 - 0.200000 : 4 [20090728-09:07:53.988922364] msec_range[15] 0.050000 - 0.100000 : 396 [20090728-09:07:53.990885303] msec_range[16] 0.020000 - 0.050000 : 824 [20090728-09:07:53.992810762] msec_range[17] 0.010000 - 0.020000 : 24 [20090728-09:07:53.994788318] msec_range[18] 0.000000 - 0.010000 : 10 [20090728-09:07:53.996698572] [20090728-09:07:53.998640945] [ read] 0.001000 0.122696 6091.164062 39168000 [20090728-09:07:54.000519382] msec_range[0] 5000.000000 - 10000.000000 : 1 [20090728-09:07:54.002691720] msec_range[1] 2000.000000 - 5000.000000 : 31 [20090728-09:07:54.005014375] msec_range[2] 1000.000000 - 2000.000000 : 65 [20090728-09:07:54.007288033] msec_range[3] 500.000000 - 1000.000000 : 220 [20090728-09:07:54.009524167] msec_range[4] 200.000000 - 500.000000 : 2347 [20090728-09:07:54.011955000] msec_range[5] 100.000000 - 200.000000 : 11845 [20090728-09:07:54.014283160] msec_range[6] 50.000000 - 100.000000 : 13592 [20090728-09:07:54.016688856] msec_range[7] 20.000000 - 50.000000 : 17369 [20090728-09:07:54.018894234] msec_range[8] 10.000000 - 20.000000 : 13196 [20090728-09:07:54.021082280] msec_range[9] 5.000000 - 10.000000 : 17574 [20090728-09:07:54.023155076] msec_range[10] 2.000000 - 5.000000 : 24547 [20090728-09:07:54.025167808] msec_range[11] 1.000000 - 2.000000 : 3990 [20090728-09:07:54.027111198] msec_range[12] 0.500000 - 1.000000 : 2381 [20090728-09:07:54.029149602] msec_range[13] 0.200000 - 0.500000 : 3166 [20090728-09:07:54.031227538] msec_range[14] 0.100000 - 0.200000 : 6030 [20090728-09:07:54.033535260] msec_range[15] 0.050000 - 0.100000 : 9371 [20090728-09:07:54.035977266] msec_range[16] 0.020000 - 0.050000 : 12129 [20090728-09:07:54.038084674] msec_range[17] 0.010000 - 0.020000 : 708918 [20090728-09:07:54.040121909] msec_range[18] 0.000000 - 0.010000 : 38321228 [20090728-09:07:54.042373816] [20090728-09:07:54.044446422] [ close] 0.002000 0.008267 0.066000 1530 [20090728-09:07:54.046445360] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-09:07:54.048324424] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-09:07:54.050456962] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-09:07:54.052578783] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-09:07:54.055314872] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-09:07:54.057613041] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-09:07:54.059823711] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-09:07:54.061941776] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-09:07:54.063961901] msec_range[8] 10.000000 - 20.000000 : 0 [20090728-09:07:54.066120667] msec_range[9] 5.000000 - 10.000000 : 0 [20090728-09:07:54.068131706] msec_range[10] 2.000000 - 5.000000 : 0 [20090728-09:07:54.070329411] msec_range[11] 1.000000 - 2.000000 : 0 [20090728-09:07:54.072347059] msec_range[12] 0.500000 - 1.000000 : 0 [20090728-09:07:54.074351479] msec_range[13] 0.200000 - 0.500000 : 0 [20090728-09:07:54.076283032] msec_range[14] 0.100000 - 0.200000 : 0 [20090728-09:07:54.078278420] msec_range[15] 0.050000 - 0.100000 : 1 [20090728-09:07:54.080339891] msec_range[16] 0.020000 - 0.050000 : 3 [20090728-09:07:54.082264833] msec_range[17] 0.010000 - 0.020000 : 189 [20090728-09:07:54.084288387] msec_range[18] 0.000000 - 0.010000 : 1337 [20090728-09:07:54.086238021] [20090728-09:07:54.088227657] [20090728-09:07:54.090197315] [20090728-09:07:54.092146228] [20090728-09:07:54.094223044] 8.2% User Time [20090728-09:07:54.096237383] 143.6% System Time [20090728-09:07:54.098118834] 151.8% CPU Utilization [20090728-09:07:54.100075188] Profilers reporting [20090728-09:07:54.463952970] Profilers postprocessing [20090728-09:07:54.734623198] Processing File : iostat.001 [20090728-09:07:54.736975881] Discovered iostat_interval=[5] [20090728-09:07:55.514146047] Processing Directory : sar.breakout.001 [20090728-09:07:55.516602611] Discovered sar_interval=[5] [20090728-09:07:55.700886509] Processing File : mpstat.001 [20090728-09:07:55.703179478] Discovered mpstat_interval=[5] [20090728-09:07:57.226646300] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-07-28_0851/btrfsexp-7-24' [20090728-09:08:02.002598091] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090728-09:08:04.479928832] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090728-09:08:04.790637104] ONLY : Command [run sequential_reads__threads_0128 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb reuse=1 num_threads=128] found for me [20090728-09:08:04.845040619] PROCESSING COMMAND : 'run sequential_reads__threads_0128 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb reuse=1 num_threads=128' [20090728-09:08:04.894123253] new log requested [20090728-09:08:04.933680462] Running command ffsb [20090728-09:08:16.186524011] 07/28/2009-09:08:16 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb Succeeded [20090728-09:08:16.197971534] Importing argument : reuse=1 [20090728-09:08:16.211893089] Importing argument : num_threads=128 [20090728-09:08:16.240435780] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090728-09:08:16.324783261] FFSB version 6.0-RC2.1 started [20090728-09:08:16.327083642] [20090728-09:08:16.861796519] benchmark time = 300 [20090728-09:08:16.863961849] ThreadGroup 0 [20090728-09:08:16.866144440] ================ [20090728-09:08:16.868351846] num_threads = 128 [20090728-09:08:16.870389384] [20090728-09:08:16.872360993] read_random = off [20090728-09:08:16.874246811] read_size = 0 (0B) [20090728-09:08:16.876221779] read_blocksize = 4096 (4KB) [20090728-09:08:16.878110211] read_skip = off [20090728-09:08:16.880044026] read_skipsize = 0 (0B) [20090728-09:08:16.881925462] [20090728-09:08:16.883952337] write_random = off [20090728-09:08:16.885839689] write_size = 0 (0B) [20090728-09:08:16.887700685] fsync_file = 0 [20090728-09:08:16.889597189] write_blocksize = 0 (0B) [20090728-09:08:16.891558531] wait time = 0 [20090728-09:08:16.893420272] [20090728-09:08:16.895352226] op weights [20090728-09:08:16.897197145] read = 0 (0.00%) [20090728-09:08:16.899361601] readall = 1 (100.00%) [20090728-09:08:16.901202257] write = 0 (0.00%) [20090728-09:08:16.903121428] create = 0 (0.00%) [20090728-09:08:16.905009420] append = 0 (0.00%) [20090728-09:08:16.906971103] delete = 0 (0.00%) [20090728-09:08:16.908824733] metaop = 0 (0.00%) [20090728-09:08:16.910758668] createdir = 0 (0.00%) [20090728-09:08:16.912641714] stat = 0 (0.00%) [20090728-09:08:16.914569348] writeall = 0 (0.00%) [20090728-09:08:16.916430598] writeall_fsync = 0 (0.00%) [20090728-09:08:16.918352225] open_close = 0 (0.00%) [20090728-09:08:16.920194344] write_fsync = 0 (0.00%) [20090728-09:08:16.922125350] create_fsync = 0 (0.00%) [20090728-09:08:16.923979678] append_fsync = 0 (0.00%) [20090728-09:08:16.925895247] [20090728-09:08:16.927768928] FileSystem /mnt/ffsb1 [20090728-09:08:16.929695573] ========== [20090728-09:08:16.931557326] num_dirs = 0 [20090728-09:08:16.933529463] starting files = 1024 [20090728-09:08:16.935406063] [20090728-09:08:16.937337885] min file size = 104857600 (100MB) [20090728-09:08:16.939218128] max file size = 104857600 (100MB) [20090728-09:08:16.941135674] directio = off [20090728-09:08:16.943001993] alignedio = on [20090728-09:08:16.944948224] bufferedio = off [20090728-09:08:16.946813485] [20090728-09:08:16.948712003] aging is off [20090728-09:08:16.950653963] current utilization = 4.48% [20090728-09:08:16.952584703] [20090728-09:08:16.954458863] checking existing fs: /mnt/ffsb1 [20090728-09:08:17.226224342] fs setup took 0 secs [20090728-09:08:18.826674137] Syncing()...1 sec [20090728-09:08:18.834619871] Starting Actual Benchmark At: Tue Jul 28 09:08:18 2009 [20090728-09:08:18.850637009] [20090728-09:13:33.347405394] Syncing()...0 sec [20090728-09:13:33.382803508] FFSB benchmark finished at: Tue Jul 28 09:13:32 2009 [20090728-09:13:33.385403627] [20090728-09:13:33.388024126] Results: [20090728-09:13:33.437164111] Benchmark took 314.16 sec [20090728-09:13:33.439165693] [20090728-09:13:33.441455376] Total Results [20090728-09:13:33.456372447] =============== [20090728-09:13:33.458866548] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090728-09:13:33.461151455] ======= ============ ========= ======= =========== ========== [20090728-09:13:33.463148631] readall : 46694400 148633.74 100.000% 100.000% 581MB/sec [20090728-09:13:33.465205239] - [20090728-09:13:33.467457158] 148633.74 Transactions per Second [20090728-09:13:33.469912970] [20090728-09:13:33.472018880] Throughput Results [20090728-09:13:33.486778014] =================== [20090728-09:13:33.488713223] Read Throughput: 581MB/sec [20090728-09:13:33.490783966] [20090728-09:13:33.492951956] System Call Latency statistics in millisecs [20090728-09:13:33.495117571] ===== [20090728-09:13:33.497319026] Min Avg Max Total Calls [20090728-09:13:33.499589038] ======== ======== ======== ============ [20090728-09:13:33.501892855] [ open] 0.006000 437.280060 7771.090820 1824 [20090728-09:13:33.503919296] msec_range[0] 5000.000000 - 10000.000000 : 19 [20090728-09:13:33.506115661] msec_range[1] 2000.000000 - 5000.000000 : 153 [20090728-09:13:33.508255272] msec_range[2] 1000.000000 - 2000.000000 : 78 [20090728-09:13:33.510452177] msec_range[3] 500.000000 - 1000.000000 : 46 [20090728-09:13:33.512483356] msec_range[4] 200.000000 - 500.000000 : 60 [20090728-09:13:33.514563412] msec_range[5] 100.000000 - 200.000000 : 46 [20090728-09:13:33.516624397] msec_range[6] 50.000000 - 100.000000 : 22 [20090728-09:13:33.518593602] msec_range[7] 20.000000 - 50.000000 : 26 [20090728-09:13:33.520832866] msec_range[8] 10.000000 - 20.000000 : 14 [20090728-09:13:33.522889821] msec_range[9] 5.000000 - 10.000000 : 16 [20090728-09:13:33.524869827] msec_range[10] 2.000000 - 5.000000 : 5 [20090728-09:13:33.526992388] msec_range[11] 1.000000 - 2.000000 : 1 [20090728-09:13:33.529133102] msec_range[12] 0.500000 - 1.000000 : 0 [20090728-09:13:33.531290810] msec_range[13] 0.200000 - 0.500000 : 0 [20090728-09:13:33.533225752] msec_range[14] 0.100000 - 0.200000 : 6 [20090728-09:13:33.535248087] msec_range[15] 0.050000 - 0.100000 : 228 [20090728-09:13:33.537175664] msec_range[16] 0.020000 - 0.050000 : 943 [20090728-09:13:33.539164794] msec_range[17] 0.010000 - 0.020000 : 100 [20090728-09:13:33.541041760] msec_range[18] 0.000000 - 0.010000 : 61 [20090728-09:13:33.542976457] [20090728-09:13:33.544938644] [ read] 0.001000 0.832618 19734.656250 46694400 [20090728-09:13:33.546935099] msec_range[0] 5000.000000 - 10000.000000 : 212 [20090728-09:13:33.548794511] msec_range[1] 2000.000000 - 5000.000000 : 1731 [20090728-09:13:33.550744948] msec_range[2] 1000.000000 - 2000.000000 : 4910 [20090728-09:13:33.552664360] msec_range[3] 500.000000 - 1000.000000 : 15179 [20090728-09:13:33.554616395] msec_range[4] 200.000000 - 500.000000 : 30493 [20090728-09:13:33.556540888] msec_range[5] 100.000000 - 200.000000 : 21527 [20090728-09:13:33.558506573] msec_range[6] 50.000000 - 100.000000 : 17024 [20090728-09:13:33.560442406] msec_range[7] 20.000000 - 50.000000 : 16304 [20090728-09:13:33.562396293] msec_range[8] 10.000000 - 20.000000 : 8858 [20090728-09:13:33.564280795] msec_range[9] 5.000000 - 10.000000 : 9294 [20090728-09:13:33.566230423] msec_range[10] 2.000000 - 5.000000 : 10683 [20090728-09:13:33.568171204] msec_range[11] 1.000000 - 2.000000 : 2588 [20090728-09:13:33.570165505] msec_range[12] 0.500000 - 1.000000 : 2112 [20090728-09:13:33.572044692] msec_range[13] 0.200000 - 0.500000 : 2438 [20090728-09:13:33.574029257] msec_range[14] 0.100000 - 0.200000 : 4296 [20090728-09:13:33.575915521] msec_range[15] 0.050000 - 0.100000 : 18793 [20090728-09:13:33.578154224] msec_range[16] 0.020000 - 0.050000 : 41861 [20090728-09:13:33.580360844] msec_range[17] 0.010000 - 0.020000 : 1647209 [20090728-09:13:33.582310768] msec_range[18] 0.000000 - 0.010000 : 44838873 [20090728-09:13:33.584328374] [20090728-09:13:33.586250784] [ close] 0.002000 0.486890 862.739990 1824 [20090728-09:13:33.588244734] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-09:13:33.590151238] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-09:13:33.592605284] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-09:13:33.594819008] msec_range[3] 500.000000 - 1000.000000 : 1 [20090728-09:13:33.597040131] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-09:13:33.599540501] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-09:13:33.601635293] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-09:13:33.603989452] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-09:13:33.606502580] msec_range[8] 10.000000 - 20.000000 : 0 [20090728-09:13:33.608770125] msec_range[9] 5.000000 - 10.000000 : 1 [20090728-09:13:33.610789267] msec_range[10] 2.000000 - 5.000000 : 1 [20090728-09:13:33.613144126] msec_range[11] 1.000000 - 2.000000 : 0 [20090728-09:13:33.615482487] msec_range[12] 0.500000 - 1.000000 : 0 [20090728-09:13:33.617736325] msec_range[13] 0.200000 - 0.500000 : 0 [20090728-09:13:33.620041616] msec_range[14] 0.100000 - 0.200000 : 1 [20090728-09:13:33.622114420] msec_range[15] 0.050000 - 0.100000 : 1 [20090728-09:13:33.624134203] msec_range[16] 0.020000 - 0.050000 : 3 [20090728-09:13:33.626218540] msec_range[17] 0.010000 - 0.020000 : 441 [20090728-09:13:33.628441931] msec_range[18] 0.000000 - 0.010000 : 1375 [20090728-09:13:33.630911736] [20090728-09:13:33.633292826] [20090728-09:13:33.635390439] [20090728-09:13:33.637517149] [20090728-09:13:33.639659515] 10.2% User Time [20090728-09:13:33.642030265] 232.3% System Time [20090728-09:13:33.644015782] 242.5% CPU Utilization [20090728-09:13:33.646078539] Profilers reporting [20090728-09:13:34.004017658] Profilers postprocessing [20090728-09:13:34.272970397] Processing File : iostat.001 [20090728-09:13:34.276211265] Discovered iostat_interval=[5] [20090728-09:13:35.065089706] Processing Directory : sar.breakout.001 [20090728-09:13:35.067224867] Discovered sar_interval=[5] [20090728-09:13:35.249260196] Processing File : mpstat.001 [20090728-09:13:35.251454421] Discovered mpstat_interval=[5] [20090728-09:13:36.761327450] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-07-28_0851/btrfsexp-7-24' [20090728-09:13:45.053676273] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090728-09:13:47.931504729] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090728-09:13:48.269103485] ONLY : Command [run random_reads__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb reuse=1 num_threads=1] found for me [20090728-09:13:48.322466821] PROCESSING COMMAND : 'run random_reads__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb reuse=1 num_threads=1' [20090728-09:13:48.371445664] new log requested [20090728-09:13:48.414377485] Running command ffsb [20090728-09:13:59.831139640] 07/28/2009-09:13:59 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb Succeeded [20090728-09:13:59.842278412] Importing argument : reuse=1 [20090728-09:13:59.856061476] Importing argument : num_threads=1 [20090728-09:13:59.885356706] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090728-09:13:59.972541225] FFSB version 6.0-RC2.1 started [20090728-09:13:59.974970034] [20090728-09:13:59.977067704] benchmark time = 300 [20090728-09:13:59.979149738] ThreadGroup 0 [20090728-09:13:59.981262496] ================ [20090728-09:13:59.983224375] num_threads = 1 [20090728-09:13:59.985217552] [20090728-09:13:59.987069874] read_random = on [20090728-09:13:59.989069627] read_size = 5242880 (5MB) [20090728-09:13:59.990938033] read_blocksize = 4096 (4KB) [20090728-09:13:59.992869108] read_skip = off [20090728-09:13:59.994752656] read_skipsize = 0 (0B) [20090728-09:13:59.996769181] [20090728-09:13:59.998678088] write_random = off [20090728-09:14:00.000646517] write_size = 0 (0B) [20090728-09:14:00.002474698] fsync_file = 0 [20090728-09:14:00.004351344] write_blocksize = 0 (0B) [20090728-09:14:00.006278712] wait time = 0 [20090728-09:14:00.008220643] [20090728-09:14:00.010018090] op weights [20090728-09:14:00.011985131] read = 1 (100.00%) [20090728-09:14:00.013865397] readall = 0 (0.00%) [20090728-09:14:00.015802128] write = 0 (0.00%) [20090728-09:14:00.017663771] create = 0 (0.00%) [20090728-09:14:00.019595954] append = 0 (0.00%) [20090728-09:14:00.021497225] delete = 0 (0.00%) [20090728-09:14:00.023391689] metaop = 0 (0.00%) [20090728-09:14:00.025271101] createdir = 0 (0.00%) [20090728-09:14:00.027234836] stat = 0 (0.00%) [20090728-09:14:00.029099738] writeall = 0 (0.00%) [20090728-09:14:00.031038938] writeall_fsync = 0 (0.00%) [20090728-09:14:00.032908084] open_close = 0 (0.00%) [20090728-09:14:00.034871026] write_fsync = 0 (0.00%) [20090728-09:14:00.036804427] create_fsync = 0 (0.00%) [20090728-09:14:00.038725851] append_fsync = 0 (0.00%) [20090728-09:14:00.040562230] [20090728-09:14:00.042636463] FileSystem /mnt/ffsb1 [20090728-09:14:00.044571328] ========== [20090728-09:14:00.046520386] num_dirs = 0 [20090728-09:14:00.048389895] starting files = 1024 [20090728-09:14:00.050392135] [20090728-09:14:00.052279485] min file size = 104857600 (100MB) [20090728-09:14:00.054208055] max file size = 104857600 (100MB) [20090728-09:14:00.056010767] directio = off [20090728-09:14:00.057991369] alignedio = on [20090728-09:14:00.059864049] bufferedio = off [20090728-09:14:00.061782433] [20090728-09:14:00.063628813] aging is off [20090728-09:14:00.065731369] current utilization = 4.48% [20090728-09:14:00.067572014] [20090728-09:14:00.069520540] checking existing fs: /mnt/ffsb1 [20090728-09:14:00.364701785] fs setup took 0 secs [20090728-09:14:01.953665942] Syncing()...1 sec [20090728-09:14:01.956205181] Starting Actual Benchmark At: Tue Jul 28 09:14:01 2009 [20090728-09:14:01.971672761] [20090728-09:19:02.909784661] Syncing()...0 sec [20090728-09:19:02.912379301] FFSB benchmark finished at: Tue Jul 28 09:19:02 2009 [20090728-09:19:02.914865361] [20090728-09:19:02.917268179] Results: [20090728-09:19:02.932802418] Benchmark took 300.95 sec [20090728-09:19:02.934866343] [20090728-09:19:02.937103404] Total Results [20090728-09:19:02.951937930] =============== [20090728-09:19:02.954231412] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090728-09:19:02.956249831] ======= ============ ========= ======= =========== ========== [20090728-09:19:02.958512553] read : 151040 501.87 100.000% 100.000% 1.96MB/sec [20090728-09:19:02.960557141] - [20090728-09:19:02.962502674] 501.87 Transactions per Second [20090728-09:19:02.964405444] [20090728-09:19:02.966381309] Throughput Results [20090728-09:19:02.983103639] =================== [20090728-09:19:02.985447904] Read Throughput: 1.96MB/sec [20090728-09:19:02.988943990] [20090728-09:19:02.991530400] System Call Latency statistics in millisecs [20090728-09:19:02.993779715] ===== [20090728-09:19:02.996744565] Min Avg Max Total Calls [20090728-09:19:03.001590009] ======== ======== ======== ============ [20090728-09:19:03.004119478] [ open] 0.012000 0.019424 0.031000 118 [20090728-09:19:03.006522787] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-09:19:03.008712770] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-09:19:03.011028244] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-09:19:03.013338220] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-09:19:03.015563470] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-09:19:03.017844409] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-09:19:03.030861394] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-09:19:03.033452993] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-09:19:03.035755641] msec_range[8] 10.000000 - 20.000000 : 0 [20090728-09:19:03.038077923] msec_range[9] 5.000000 - 10.000000 : 0 [20090728-09:19:03.040395564] msec_range[10] 2.000000 - 5.000000 : 0 [20090728-09:19:03.042647169] msec_range[11] 1.000000 - 2.000000 : 0 [20090728-09:19:03.045551545] msec_range[12] 0.500000 - 1.000000 : 0 [20090728-09:19:03.048041635] msec_range[13] 0.200000 - 0.500000 : 0 [20090728-09:19:03.050110273] msec_range[14] 0.100000 - 0.200000 : 0 [20090728-09:19:03.052142319] msec_range[15] 0.050000 - 0.100000 : 0 [20090728-09:19:03.054146904] msec_range[16] 0.020000 - 0.050000 : 65 [20090728-09:19:03.056064101] msec_range[17] 0.010000 - 0.020000 : 53 [20090728-09:19:03.058233907] msec_range[18] 0.000000 - 0.010000 : 0 [20090728-09:19:03.060325875] [20090728-09:19:03.062626595] [ read] 0.002000 1.989641 82.771004 151040 [20090728-09:19:03.064891796] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-09:19:03.067503393] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-09:19:03.069751832] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-09:19:03.072009528] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-09:19:03.074139368] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-09:19:03.076283040] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-09:19:03.078401471] msec_range[6] 50.000000 - 100.000000 : 1 [20090728-09:19:03.080730182] msec_range[7] 20.000000 - 50.000000 : 102 [20090728-09:19:03.083057659] msec_range[8] 10.000000 - 20.000000 : 987 [20090728-09:19:03.085258197] msec_range[9] 5.000000 - 10.000000 : 13628 [20090728-09:19:03.087711904] msec_range[10] 2.000000 - 5.000000 : 42868 [20090728-09:19:03.090052486] msec_range[11] 1.000000 - 2.000000 : 9085 [20090728-09:19:03.092300811] msec_range[12] 0.500000 - 1.000000 : 355 [20090728-09:19:03.094449805] msec_range[13] 0.200000 - 0.500000 : 79725 [20090728-09:19:03.096507139] msec_range[14] 0.100000 - 0.200000 : 296 [20090728-09:19:03.098891623] msec_range[15] 0.050000 - 0.100000 : 0 [20090728-09:19:03.101015567] msec_range[16] 0.020000 - 0.050000 : 0 [20090728-09:19:03.103223137] msec_range[17] 0.010000 - 0.020000 : 25 [20090728-09:19:03.105440233] msec_range[18] 0.000000 - 0.010000 : 3968 [20090728-09:19:03.107439257] [20090728-09:19:03.109922510] [ lseek] 0.000000 0.001447 0.008000 151040 [20090728-09:19:03.112397146] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-09:19:03.114338968] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-09:19:03.116558469] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-09:19:03.118656650] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-09:19:03.120687947] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-09:19:03.122657883] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-09:19:03.124923840] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-09:19:03.127078608] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-09:19:03.129157404] msec_range[8] 10.000000 - 20.000000 : 0 [20090728-09:19:03.132152854] msec_range[9] 5.000000 - 10.000000 : 0 [20090728-09:19:03.134419572] msec_range[10] 2.000000 - 5.000000 : 0 [20090728-09:19:03.136357671] msec_range[11] 1.000000 - 2.000000 : 0 [20090728-09:19:03.138398899] msec_range[12] 0.500000 - 1.000000 : 0 [20090728-09:19:03.140505066] msec_range[13] 0.200000 - 0.500000 : 0 [20090728-09:19:03.142584046] msec_range[14] 0.100000 - 0.200000 : 0 [20090728-09:19:03.144544015] msec_range[15] 0.050000 - 0.100000 : 0 [20090728-09:19:03.146809576] msec_range[16] 0.020000 - 0.050000 : 0 [20090728-09:19:03.148864734] msec_range[17] 0.010000 - 0.020000 : 0 [20090728-09:19:03.150982577] msec_range[18] 0.000000 - 0.010000 : 151040 [20090728-09:19:03.153238977] [20090728-09:19:03.155289174] [ close] 0.003000 0.005763 0.012000 118 [20090728-09:19:03.157309446] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-09:19:03.159329921] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-09:19:03.161445651] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-09:19:03.163666563] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-09:19:03.165653834] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-09:19:03.167638905] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-09:19:03.169579043] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-09:19:03.171531503] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-09:19:03.173572976] msec_range[8] 10.000000 - 20.000000 : 0 [20090728-09:19:03.175491672] msec_range[9] 5.000000 - 10.000000 : 0 [20090728-09:19:03.177510920] msec_range[10] 2.000000 - 5.000000 : 0 [20090728-09:19:03.179461243] msec_range[11] 1.000000 - 2.000000 : 0 [20090728-09:19:03.181492206] msec_range[12] 0.500000 - 1.000000 : 0 [20090728-09:19:03.183425384] msec_range[13] 0.200000 - 0.500000 : 0 [20090728-09:19:03.185399660] msec_range[14] 0.100000 - 0.200000 : 0 [20090728-09:19:03.187427891] msec_range[15] 0.050000 - 0.100000 : 0 [20090728-09:19:03.189350665] msec_range[16] 0.020000 - 0.050000 : 0 [20090728-09:19:03.191349202] msec_range[17] 0.010000 - 0.020000 : 1 [20090728-09:19:03.193267939] msec_range[18] 0.000000 - 0.010000 : 117 [20090728-09:19:03.195227605] [20090728-09:19:03.197125215] [20090728-09:19:03.199097029] [20090728-09:19:03.201096703] [20090728-09:19:03.202994788] 0.1% User Time [20090728-09:19:03.205000282] 2.1% System Time [20090728-09:19:03.206901377] 2.2% CPU Utilization [20090728-09:19:03.208900758] Profilers reporting [20090728-09:19:03.210806859] /autobench/scripts/doprofilers: line 2: 6515 Terminated ${CMDS[$i]} [20090728-09:19:03.212847865] /autobench/scripts/doprofilers: line 2: 6533 Terminated ${CMDS[$i]} [20090728-09:19:03.214918856] /autobench/scripts/doprofilers: line 2: 6567 Terminated ${CMDS[$i]} [20090728-09:19:03.216871028] Profilers postprocessing [20090728-09:19:03.219176008] Processing File : iostat.001 [20090728-09:19:03.221193624] Discovered iostat_interval=[5] [20090728-09:19:03.931335499] Processing Directory : sar.breakout.001 [20090728-09:19:03.933692329] Discovered sar_interval=[5] [20090728-09:19:04.103267042] Processing File : mpstat.001 [20090728-09:19:04.105793313] Discovered mpstat_interval=[5] [20090728-09:19:04.939929894] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-07-28_0851/btrfsexp-7-24' [20090728-09:19:08.646491270] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090728-09:19:09.254496481] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090728-09:19:09.557901939] ONLY : Command [run random_reads__threads_0016 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb reuse=1 num_threads=16] found for me [20090728-09:19:09.611515751] PROCESSING COMMAND : 'run random_reads__threads_0016 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb reuse=1 num_threads=16' [20090728-09:19:09.661313877] new log requested [20090728-09:19:09.691274135] Running command ffsb [20090728-09:19:19.623765200] 07/28/2009-09:19:19 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb Succeeded [20090728-09:19:19.635090102] Importing argument : reuse=1 [20090728-09:19:19.648937467] Importing argument : num_threads=16 [20090728-09:19:19.677053129] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090728-09:19:19.751597202] FFSB version 6.0-RC2.1 started [20090728-09:19:19.753915539] [20090728-09:19:19.818340516] benchmark time = 300 [20090728-09:19:19.820537510] ThreadGroup 0 [20090728-09:19:19.822597950] ================ [20090728-09:19:19.824554703] num_threads = 16 [20090728-09:19:19.826577245] [20090728-09:19:19.828480186] read_random = on [20090728-09:19:19.830440114] read_size = 5242880 (5MB) [20090728-09:19:19.832352760] read_blocksize = 4096 (4KB) [20090728-09:19:19.834294791] read_skip = off [20090728-09:19:19.836124929] read_skipsize = 0 (0B) [20090728-09:19:19.838064399] [20090728-09:19:19.839939472] write_random = off [20090728-09:19:19.841872224] write_size = 0 (0B) [20090728-09:19:19.843743842] fsync_file = 0 [20090728-09:19:19.845667424] write_blocksize = 0 (0B) [20090728-09:19:19.847527653] wait time = 0 [20090728-09:19:19.849391793] [20090728-09:19:19.851259210] op weights [20090728-09:19:19.853210266] read = 1 (100.00%) [20090728-09:19:19.855095934] readall = 0 (0.00%) [20090728-09:19:19.857013833] write = 0 (0.00%) [20090728-09:19:19.858872134] create = 0 (0.00%) [20090728-09:19:19.860790154] append = 0 (0.00%) [20090728-09:19:19.862672140] delete = 0 (0.00%) [20090728-09:19:19.864597509] metaop = 0 (0.00%) [20090728-09:19:19.866447881] createdir = 0 (0.00%) [20090728-09:19:19.868408473] stat = 0 (0.00%) [20090728-09:19:19.870269704] writeall = 0 (0.00%) [20090728-09:19:19.872194288] writeall_fsync = 0 (0.00%) [20090728-09:19:19.873985523] open_close = 0 (0.00%) [20090728-09:19:19.875956789] write_fsync = 0 (0.00%) [20090728-09:19:19.877900940] create_fsync = 0 (0.00%) [20090728-09:19:19.879842952] append_fsync = 0 (0.00%) [20090728-09:19:19.881671864] [20090728-09:19:19.883577290] FileSystem /mnt/ffsb1 [20090728-09:19:19.885454329] ========== [20090728-09:19:19.887412968] num_dirs = 0 [20090728-09:19:19.889214250] starting files = 1024 [20090728-09:19:19.891192684] [20090728-09:19:19.893096167] min file size = 104857600 (100MB) [20090728-09:19:19.895020016] max file size = 104857600 (100MB) [20090728-09:19:19.896857266] directio = off [20090728-09:19:19.898805089] alignedio = on [20090728-09:19:19.900706052] bufferedio = off [20090728-09:19:19.902618093] [20090728-09:19:19.904457285] aging is off [20090728-09:19:19.906431718] current utilization = 4.48% [20090728-09:19:19.908384062] [20090728-09:19:19.910319774] checking existing fs: /mnt/ffsb1 [20090728-09:19:20.232776488] fs setup took 0 secs [20090728-09:19:21.759274239] Syncing()...1 sec [20090728-09:19:21.761933662] Starting Actual Benchmark At: Tue Jul 28 09:19:21 2009 [20090728-09:19:21.781954084] [20090728-09:24:26.088527030] Syncing()...0 sec [20090728-09:24:26.108817971] FFSB benchmark finished at: Tue Jul 28 09:24:26 2009 [20090728-09:24:26.111380462] [20090728-09:24:26.113928878] Results: [20090728-09:24:26.139394950] Benchmark took 304.27 sec [20090728-09:24:26.141705229] [20090728-09:24:26.144153422] Total Results [20090728-09:24:26.159558183] =============== [20090728-09:24:26.162222843] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090728-09:24:26.165400837] ======= ============ ========= ======= =========== ========== [20090728-09:24:26.167813054] read : 1442560 4741.13 100.000% 100.000% 18.5MB/sec [20090728-09:24:26.170359352] - [20090728-09:24:26.172939738] 4741.13 Transactions per Second [20090728-09:24:26.175359594] [20090728-09:24:26.177572493] Throughput Results [20090728-09:24:26.192947092] =================== [20090728-09:24:26.195200322] Read Throughput: 18.5MB/sec [20090728-09:24:26.197603401] [20090728-09:24:26.199980876] System Call Latency statistics in millisecs [20090728-09:24:26.202378970] ===== [20090728-09:24:26.204673743] Min Avg Max Total Calls [20090728-09:24:26.206770249] ======== ======== ======== ============ [20090728-09:24:26.209001626] [ open] 0.007000 0.022125 0.095000 1127 [20090728-09:24:26.211091870] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-09:24:26.213354566] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-09:24:26.215584309] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-09:24:26.217789312] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-09:24:26.220009817] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-09:24:26.222031444] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-09:24:26.224049557] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-09:24:26.226041496] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-09:24:26.228085046] msec_range[8] 10.000000 - 20.000000 : 0 [20090728-09:24:26.230055444] msec_range[9] 5.000000 - 10.000000 : 0 [20090728-09:24:26.232034418] msec_range[10] 2.000000 - 5.000000 : 0 [20090728-09:24:26.234023204] msec_range[11] 1.000000 - 2.000000 : 0 [20090728-09:24:26.236028289] msec_range[12] 0.500000 - 1.000000 : 0 [20090728-09:24:26.237949785] msec_range[13] 0.200000 - 0.500000 : 0 [20090728-09:24:26.239985610] msec_range[14] 0.100000 - 0.200000 : 0 [20090728-09:24:26.242181118] msec_range[15] 0.050000 - 0.100000 : 23 [20090728-09:24:26.244614356] msec_range[16] 0.020000 - 0.050000 : 800 [20090728-09:24:26.247066663] msec_range[17] 0.010000 - 0.020000 : 277 [20090728-09:24:26.249569868] msec_range[18] 0.000000 - 0.010000 : 27 [20090728-09:24:26.251803262] [20090728-09:24:26.254201397] [ read] 0.001000 3.356545 150.449005 1442560 [20090728-09:24:26.256874024] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-09:24:26.261767546] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-09:24:26.264195186] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-09:24:26.266710789] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-09:24:26.269398132] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-09:24:26.273188979] msec_range[5] 100.000000 - 200.000000 : 4 [20090728-09:24:26.275584893] msec_range[6] 50.000000 - 100.000000 : 9 [20090728-09:24:26.277782499] msec_range[7] 20.000000 - 50.000000 : 362 [20090728-09:24:26.280066975] msec_range[8] 10.000000 - 20.000000 : 8928 [20090728-09:24:26.282275701] msec_range[9] 5.000000 - 10.000000 : 313980 [20090728-09:24:26.284682960] msec_range[10] 2.000000 - 5.000000 : 743080 [20090728-09:24:26.286939378] msec_range[11] 1.000000 - 2.000000 : 56091 [20090728-09:24:26.289094609] msec_range[12] 0.500000 - 1.000000 : 10846 [20090728-09:24:26.292985633] msec_range[13] 0.200000 - 0.500000 : 236723 [20090728-09:24:26.295427273] msec_range[14] 0.100000 - 0.200000 : 180 [20090728-09:24:26.297865951] msec_range[15] 0.050000 - 0.100000 : 33 [20090728-09:24:26.300894949] msec_range[16] 0.020000 - 0.050000 : 127 [20090728-09:24:26.303283094] msec_range[17] 0.010000 - 0.020000 : 792 [20090728-09:24:26.305893753] msec_range[18] 0.000000 - 0.010000 : 71405 [20090728-09:24:26.308386043] [20090728-09:24:26.310969752] [ lseek] 0.000000 0.001527 0.126000 1442560 [20090728-09:24:26.313430106] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-09:24:26.315685634] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-09:24:26.317700489] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-09:24:26.319901120] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-09:24:26.322603441] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-09:24:26.324818346] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-09:24:26.327103272] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-09:24:26.329319862] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-09:24:26.331361893] msec_range[8] 10.000000 - 20.000000 : 0 [20090728-09:24:26.333398196] msec_range[9] 5.000000 - 10.000000 : 0 [20090728-09:24:26.335654575] msec_range[10] 2.000000 - 5.000000 : 0 [20090728-09:24:26.337909453] msec_range[11] 1.000000 - 2.000000 : 0 [20090728-09:24:26.340142739] msec_range[12] 0.500000 - 1.000000 : 0 [20090728-09:24:26.342346188] msec_range[13] 0.200000 - 0.500000 : 0 [20090728-09:24:26.344485844] msec_range[14] 0.100000 - 0.200000 : 3 [20090728-09:24:26.346584854] msec_range[15] 0.050000 - 0.100000 : 54 [20090728-09:24:26.348522428] msec_range[16] 0.020000 - 0.050000 : 370 [20090728-09:24:26.350552372] msec_range[17] 0.010000 - 0.020000 : 315 [20090728-09:24:26.352542417] msec_range[18] 0.000000 - 0.010000 : 1441818 [20090728-09:24:26.354517071] [20090728-09:24:26.356609132] [ close] 0.003000 0.005949 0.026000 1127 [20090728-09:24:26.358854657] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-09:24:26.361230682] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-09:24:26.363345343] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-09:24:26.365574132] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-09:24:26.367689913] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-09:24:26.369754777] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-09:24:26.371803597] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-09:24:26.373845347] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-09:24:26.376038060] msec_range[8] 10.000000 - 20.000000 : 0 [20090728-09:24:26.378032067] msec_range[9] 5.000000 - 10.000000 : 0 [20090728-09:24:26.380056080] msec_range[10] 2.000000 - 5.000000 : 0 [20090728-09:24:26.382097521] msec_range[11] 1.000000 - 2.000000 : 0 [20090728-09:24:26.384448181] msec_range[12] 0.500000 - 1.000000 : 0 [20090728-09:24:26.386632918] msec_range[13] 0.200000 - 0.500000 : 0 [20090728-09:24:26.388623580] msec_range[14] 0.100000 - 0.200000 : 0 [20090728-09:24:26.390610949] msec_range[15] 0.050000 - 0.100000 : 0 [20090728-09:24:26.392597957] msec_range[16] 0.020000 - 0.050000 : 2 [20090728-09:24:26.394604251] msec_range[17] 0.010000 - 0.020000 : 6 [20090728-09:24:26.396688563] msec_range[18] 0.000000 - 0.010000 : 1119 [20090728-09:24:26.398875848] [20090728-09:24:26.401060933] [20090728-09:24:26.403057881] [20090728-09:24:26.405303220] [20090728-09:24:26.407376723] 1.2% User Time [20090728-09:24:26.409490310] 24.0% System Time [20090728-09:24:26.411674765] 25.2% CPU Utilization [20090728-09:24:26.413676623] Profilers reporting [20090728-09:24:26.433259306] Profilers postprocessing [20090728-09:24:26.610191606] Processing File : iostat.001 [20090728-09:24:26.612528429] Discovered iostat_interval=[5] [20090728-09:24:27.385460734] Processing Directory : sar.breakout.001 [20090728-09:24:27.387842277] Discovered sar_interval=[5] [20090728-09:24:27.564217695] Processing File : mpstat.001 [20090728-09:24:27.566600560] Discovered mpstat_interval=[5] [20090728-09:24:28.609488627] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-07-28_0851/btrfsexp-7-24' [20090728-09:24:34.190445309] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090728-09:24:37.587303016] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090728-09:24:37.938535087] ONLY : Command [run random_reads__threads_0128 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb reuse=1 num_threads=128] found for me [20090728-09:24:37.992310869] PROCESSING COMMAND : 'run random_reads__threads_0128 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb reuse=1 num_threads=128' [20090728-09:24:38.040992001] new log requested [20090728-09:24:38.068961924] Running command ffsb [20090728-09:24:48.354605948] 07/28/2009-09:24:48 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb Succeeded [20090728-09:24:48.366036617] Importing argument : reuse=1 [20090728-09:24:48.379926008] Importing argument : num_threads=128 [20090728-09:24:48.411852865] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090728-09:24:48.500125300] FFSB version 6.0-RC2.1 started [20090728-09:24:48.502225097] [20090728-09:24:49.033992654] benchmark time = 300 [20090728-09:24:49.036306056] ThreadGroup 0 [20090728-09:24:49.038388087] ================ [20090728-09:24:49.040291078] num_threads = 128 [20090728-09:24:49.042305043] [20090728-09:24:49.044272395] read_random = on [20090728-09:24:49.046268693] read_size = 5242880 (5MB) [20090728-09:24:49.048160808] read_blocksize = 4096 (4KB) [20090728-09:24:49.050106662] read_skip = off [20090728-09:24:49.052046424] read_skipsize = 0 (0B) [20090728-09:24:49.053987173] [20090728-09:24:49.055846496] write_random = off [20090728-09:24:49.057756897] write_size = 0 (0B) [20090728-09:24:49.059648227] fsync_file = 0 [20090728-09:24:49.061645244] write_blocksize = 0 (0B) [20090728-09:24:49.063520821] wait time = 0 [20090728-09:24:49.065480835] [20090728-09:24:49.067395658] op weights [20090728-09:24:49.069383793] read = 1 (100.00%) [20090728-09:24:49.071280534] readall = 0 (0.00%) [20090728-09:24:49.073201118] write = 0 (0.00%) [20090728-09:24:49.075114379] create = 0 (0.00%) [20090728-09:24:49.077052310] append = 0 (0.00%) [20090728-09:24:49.078904124] delete = 0 (0.00%) [20090728-09:24:49.080830211] metaop = 0 (0.00%) [20090728-09:24:49.082719008] createdir = 0 (0.00%) [20090728-09:24:49.084754465] stat = 0 (0.00%) [20090728-09:24:49.086950846] writeall = 0 (0.00%) [20090728-09:24:49.089200487] writeall_fsync = 0 (0.00%) [20090728-09:24:49.091564758] open_close = 0 (0.00%) [20090728-09:24:49.093759160] write_fsync = 0 (0.00%) [20090728-09:24:49.095851611] create_fsync = 0 (0.00%) [20090728-09:24:49.097701613] append_fsync = 0 (0.00%) [20090728-09:24:49.099787627] [20090728-09:24:49.101730711] FileSystem /mnt/ffsb1 [20090728-09:24:49.103761076] ========== [20090728-09:24:49.105651771] num_dirs = 0 [20090728-09:24:49.107652936] starting files = 1024 [20090728-09:24:49.109621514] [20090728-09:24:49.111632928] min file size = 104857600 (100MB) [20090728-09:24:49.113529624] max file size = 104857600 (100MB) [20090728-09:24:49.115557705] directio = off [20090728-09:24:49.117481502] alignedio = on [20090728-09:24:49.119397853] bufferedio = off [20090728-09:24:49.121268498] [20090728-09:24:49.123282133] aging is off [20090728-09:24:49.125235816] current utilization = 4.48% [20090728-09:24:49.127150591] [20090728-09:24:49.129032872] checking existing fs: /mnt/ffsb1 [20090728-09:24:49.452907786] fs setup took 0 secs [20090728-09:24:51.407352834] Syncing()...1 sec [20090728-09:24:51.413165686] Starting Actual Benchmark At: Tue Jul 28 09:24:51 2009 [20090728-09:24:51.428680923] [20090728-09:29:58.470939416] Syncing()...0 sec [20090728-09:29:58.519524980] FFSB benchmark finished at: Tue Jul 28 09:29:58 2009 [20090728-09:29:58.522067863] [20090728-09:29:58.524621871] Results: [20090728-09:29:58.561446561] Benchmark took 306.77 sec [20090728-09:29:58.563414046] [20090728-09:29:58.565628130] Total Results [20090728-09:29:58.580674882] =============== [20090728-09:29:58.583144636] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090728-09:29:58.585461606] ======= ============ ========= ======= =========== ========== [20090728-09:29:58.587540044] read : 6743040 21980.62 100.000% 100.000% 85.9MB/sec [20090728-09:29:58.589687585] - [20090728-09:29:58.592025381] 21980.62 Transactions per Second [20090728-09:29:58.594546339] [20090728-09:29:58.596695985] Throughput Results [20090728-09:29:58.611653348] =================== [20090728-09:29:58.613795708] Read Throughput: 85.9MB/sec [20090728-09:29:58.615951206] [20090728-09:29:58.618056238] System Call Latency statistics in millisecs [20090728-09:29:58.619957033] ===== [20090728-09:29:58.622795298] Min Avg Max Total Calls [20090728-09:29:58.625597098] ======== ======== ======== ============ [20090728-09:29:58.627818578] [ open] 0.006000 0.038809 12.917000 5268 [20090728-09:29:58.629976695] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-09:29:58.632208539] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-09:29:58.634261582] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-09:29:58.636338581] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-09:29:58.638301201] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-09:29:58.640275697] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-09:29:58.642185989] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-09:29:58.644260536] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-09:29:58.646243363] msec_range[8] 10.000000 - 20.000000 : 1 [20090728-09:29:58.648167614] msec_range[9] 5.000000 - 10.000000 : 5 [20090728-09:29:58.650203729] msec_range[10] 2.000000 - 5.000000 : 5 [20090728-09:29:58.652152986] msec_range[11] 1.000000 - 2.000000 : 0 [20090728-09:29:58.654132372] msec_range[12] 0.500000 - 1.000000 : 0 [20090728-09:29:58.656049038] msec_range[13] 0.200000 - 0.500000 : 2 [20090728-09:29:58.658049468] msec_range[14] 0.100000 - 0.200000 : 5 [20090728-09:29:58.659965948] msec_range[15] 0.050000 - 0.100000 : 355 [20090728-09:29:58.661929214] msec_range[16] 0.020000 - 0.050000 : 4142 [20090728-09:29:58.663839747] msec_range[17] 0.010000 - 0.020000 : 681 [20090728-09:29:58.665824346] msec_range[18] 0.000000 - 0.010000 : 72 [20090728-09:29:58.667754654] [20090728-09:29:58.670014828] [ read] 0.001000 5.760730 135.591995 6743040 [20090728-09:29:58.672251475] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-09:29:58.675037666] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-09:29:58.677670951] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-09:29:58.680057789] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-09:29:58.682663199] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-09:29:58.684972478] msec_range[5] 100.000000 - 200.000000 : 10 [20090728-09:29:58.687328318] msec_range[6] 50.000000 - 100.000000 : 265 [20090728-09:29:58.689503596] msec_range[7] 20.000000 - 50.000000 : 49171 [20090728-09:29:58.691474001] msec_range[8] 10.000000 - 20.000000 : 618469 [20090728-09:29:58.693451396] msec_range[9] 5.000000 - 10.000000 : 2934270 [20090728-09:29:58.695762940] msec_range[10] 2.000000 - 5.000000 : 2602168 [20090728-09:29:58.697921631] msec_range[11] 1.000000 - 2.000000 : 98041 [20090728-09:29:58.700060391] msec_range[12] 0.500000 - 1.000000 : 32761 [20090728-09:29:58.702173842] msec_range[13] 0.200000 - 0.500000 : 12908 [20090728-09:29:58.704325654] msec_range[14] 0.100000 - 0.200000 : 60 [20090728-09:29:58.706381364] msec_range[15] 0.050000 - 0.100000 : 232 [20090728-09:29:58.708757306] msec_range[16] 0.020000 - 0.050000 : 3452 [20090728-09:29:58.711040682] msec_range[17] 0.010000 - 0.020000 : 23724 [20090728-09:29:58.713022787] msec_range[18] 0.000000 - 0.010000 : 367509 [20090728-09:29:58.715109570] [20090728-09:29:58.717952281] [ lseek] 0.000000 0.001689 0.553000 6743040 [20090728-09:29:58.720167553] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-09:29:58.722565235] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-09:29:58.724725136] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-09:29:58.726878630] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-09:29:58.728827633] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-09:29:58.730922725] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-09:29:58.732922843] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-09:29:58.735254534] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-09:29:58.737257987] msec_range[8] 10.000000 - 20.000000 : 0 [20090728-09:29:58.739254702] msec_range[9] 5.000000 - 10.000000 : 0 [20090728-09:29:58.741363997] msec_range[10] 2.000000 - 5.000000 : 0 [20090728-09:29:58.743325148] msec_range[11] 1.000000 - 2.000000 : 0 [20090728-09:29:58.745292574] msec_range[12] 0.500000 - 1.000000 : 1 [20090728-09:29:58.747259279] msec_range[13] 0.200000 - 0.500000 : 18 [20090728-09:29:58.749220317] msec_range[14] 0.100000 - 0.200000 : 103 [20090728-09:29:58.751237523] msec_range[15] 0.050000 - 0.100000 : 595 [20090728-09:29:58.753234190] msec_range[16] 0.020000 - 0.050000 : 6645 [20090728-09:29:58.755239936] msec_range[17] 0.010000 - 0.020000 : 7362 [20090728-09:29:58.757223390] msec_range[18] 0.000000 - 0.010000 : 6728316 [20090728-09:29:58.759212106] [20090728-09:29:58.761150486] [ close] 0.002000 0.006631 0.084000 5268 [20090728-09:29:58.763133561] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-09:29:58.765179523] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-09:29:58.767199981] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-09:29:58.769127470] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-09:29:58.771125324] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-09:29:58.773506577] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-09:29:58.775515100] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-09:29:58.777445510] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-09:29:58.779424684] msec_range[8] 10.000000 - 20.000000 : 0 [20090728-09:29:58.781409003] msec_range[9] 5.000000 - 10.000000 : 0 [20090728-09:29:58.783384912] msec_range[10] 2.000000 - 5.000000 : 0 [20090728-09:29:58.785321351] msec_range[11] 1.000000 - 2.000000 : 0 [20090728-09:29:58.787282868] msec_range[12] 0.500000 - 1.000000 : 0 [20090728-09:29:58.789240635] msec_range[13] 0.200000 - 0.500000 : 0 [20090728-09:29:58.791197782] msec_range[14] 0.100000 - 0.200000 : 0 [20090728-09:29:58.793139557] msec_range[15] 0.050000 - 0.100000 : 2 [20090728-09:29:58.795121212] msec_range[16] 0.020000 - 0.050000 : 35 [20090728-09:29:58.797135900] msec_range[17] 0.010000 - 0.020000 : 55 [20090728-09:29:58.799125981] msec_range[18] 0.000000 - 0.010000 : 5176 [20090728-09:29:58.801059426] [20090728-09:29:58.803020154] [20090728-09:29:58.804943081] [20090728-09:29:58.807130813] [20090728-09:29:58.809019492] 7.0% User Time [20090728-09:29:58.810959181] 135.9% System Time [20090728-09:29:58.813012987] 142.9% CPU Utilization [20090728-09:29:58.815326478] Profilers reporting [20090728-09:29:59.121320756] Profilers postprocessing [20090728-09:29:59.394319755] Processing File : iostat.001 [20090728-09:29:59.396758036] Discovered iostat_interval=[5] [20090728-09:30:00.187305574] Processing Directory : sar.breakout.001 [20090728-09:30:00.189687254] Discovered sar_interval=[5] [20090728-09:30:00.371947745] Processing File : mpstat.001 [20090728-09:30:00.374357736] Discovered mpstat_interval=[5] [20090728-09:30:01.908092887] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-07-28_0851/btrfsexp-7-24' [20090728-09:30:07.691448913] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090728-09:30:11.807873101] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090728-09:30:12.137414349] ONLY : Command [run random_writes__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb num_threads=1] found for me [20090728-09:30:12.191226475] PROCESSING COMMAND : 'run random_writes__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb num_threads=1' [20090728-09:30:12.239588748] new log requested [20090728-09:30:12.282740780] Running command ffsb [20090728-09:30:23.454523189] 07/28/2009-09:30:23 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb Succeeded [20090728-09:30:23.465830312] Importing argument : num_threads=1 [20090728-09:30:23.495117275] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090728-09:30:23.578504957] FFSB version 6.0-RC2.1 started [20090728-09:30:23.580531090] [20090728-09:30:23.582816283] benchmark time = 300 [20090728-09:30:23.585209669] ThreadGroup 0 [20090728-09:30:23.587218295] ================ [20090728-09:30:23.589526274] num_threads = 1 [20090728-09:30:23.591683274] [20090728-09:30:23.593769033] read_random = off [20090728-09:30:23.596110323] read_size = 0 (0B) [20090728-09:30:23.598209177] read_blocksize = 0 (0B) [20090728-09:30:23.600346706] read_skip = off [20090728-09:30:23.602329200] read_skipsize = 0 (0B) [20090728-09:30:23.604315130] [20090728-09:30:23.606302615] write_random = on [20090728-09:30:23.608298763] write_size = 5242880 (5MB) [20090728-09:30:23.610228743] fsync_file = 0 [20090728-09:30:23.612207067] write_blocksize = 4096 (4KB) [20090728-09:30:23.614144286] wait time = 0 [20090728-09:30:23.616080309] [20090728-09:30:23.618187873] op weights [20090728-09:30:23.620166345] read = 0 (0.00%) [20090728-09:30:23.622260778] readall = 0 (0.00%) [20090728-09:30:23.624360553] write = 1 (100.00%) [20090728-09:30:23.626481241] create = 0 (0.00%) [20090728-09:30:23.628419686] append = 0 (0.00%) [20090728-09:30:23.630452764] delete = 0 (0.00%) [20090728-09:30:23.632427264] metaop = 0 (0.00%) [20090728-09:30:23.634377459] createdir = 0 (0.00%) [20090728-09:30:23.636287913] stat = 0 (0.00%) [20090728-09:30:23.638297277] writeall = 0 (0.00%) [20090728-09:30:23.640240914] writeall_fsync = 0 (0.00%) [20090728-09:30:23.642215779] open_close = 0 (0.00%) [20090728-09:30:23.644099278] write_fsync = 0 (0.00%) [20090728-09:30:23.646043067] create_fsync = 0 (0.00%) [20090728-09:30:23.647968386] append_fsync = 0 (0.00%) [20090728-09:30:23.649981269] [20090728-09:30:23.652094269] FileSystem /mnt/ffsb1 [20090728-09:30:23.654103642] ========== [20090728-09:30:23.656194554] num_dirs = 0 [20090728-09:30:23.658153558] starting files = 1024 [20090728-09:30:23.660225192] [20090728-09:30:23.662151715] min file size = 104857600 (100MB) [20090728-09:30:23.664160540] max file size = 104857600 (100MB) [20090728-09:30:23.666064689] directio = off [20090728-09:30:23.668023916] alignedio = on [20090728-09:30:23.669916210] bufferedio = off [20090728-09:30:23.671902014] [20090728-09:30:23.673802739] aging is off [20090728-09:30:23.675784017] current utilization = 4.48% [20090728-09:30:23.677628565] [20090728-09:30:23.679632483] creating new fileset /mnt/ffsb1 [20090728-09:36:17.293969678] fs setup took 353 secs [20090728-09:36:19.047461075] Syncing()...2 sec [20090728-09:36:19.050250833] Starting Actual Benchmark At: Tue Jul 28 09:36:19 2009 [20090728-09:36:19.158792361] [20090728-09:41:38.598717207] Syncing()...18 sec [20090728-09:41:38.710294292] FFSB benchmark finished at: Tue Jul 28 09:41:38 2009 [20090728-09:41:38.713119365] [20090728-09:41:38.715886812] Results: [20090728-09:41:38.758310693] Benchmark took 319.28 sec [20090728-09:41:38.760475674] [20090728-09:41:38.762923780] Total Results [20090728-09:41:38.777894626] =============== [20090728-09:41:38.780094388] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090728-09:41:38.783085234] ======= ============ ========= ======= =========== ========== [20090728-09:41:38.785417364] write : 3134720 9817.99 100.000% 100.000% 38.4MB/sec [20090728-09:41:38.788202254] - [20090728-09:41:38.790641523] 9817.99 Transactions per Second [20090728-09:41:38.793016794] [20090728-09:41:38.795462199] Throughput Results [20090728-09:41:38.810924247] =================== [20090728-09:41:38.813380908] Write Throughput: 38.4MB/sec [20090728-09:41:38.815691727] [20090728-09:41:38.817997274] System Call Latency statistics in millisecs [20090728-09:41:38.820234056] ===== [20090728-09:41:38.822467173] Min Avg Max Total Calls [20090728-09:41:38.824829979] ======== ======== ======== ============ [20090728-09:41:38.827117373] [ open] 0.013000 0.068599 6.655000 2449 [20090728-09:41:38.829418852] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-09:41:38.831726156] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-09:41:38.833914290] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-09:41:38.836262642] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-09:41:38.838438738] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-09:41:38.840623312] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-09:41:38.842792969] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-09:41:38.845036100] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-09:41:38.847266281] msec_range[8] 10.000000 - 20.000000 : 0 [20090728-09:41:38.851182184] msec_range[9] 5.000000 - 10.000000 : 1 [20090728-09:41:38.854097688] msec_range[10] 2.000000 - 5.000000 : 5 [20090728-09:41:38.856720293] msec_range[11] 1.000000 - 2.000000 : 4 [20090728-09:41:38.859184094] msec_range[12] 0.500000 - 1.000000 : 17 [20090728-09:41:38.861628790] msec_range[13] 0.200000 - 0.500000 : 59 [20090728-09:41:38.863815224] msec_range[14] 0.100000 - 0.200000 : 296 [20090728-09:41:38.866040250] msec_range[15] 0.050000 - 0.100000 : 484 [20090728-09:41:38.868407967] msec_range[16] 0.020000 - 0.050000 : 1502 [20090728-09:41:38.870871512] msec_range[17] 0.010000 - 0.020000 : 81 [20090728-09:41:38.873356636] msec_range[18] 0.000000 - 0.010000 : 0 [20090728-09:41:38.875485118] [20090728-09:41:38.877692651] [ write] 0.008000 0.093679 2032.071045 3134720 [20090728-09:41:38.880015346] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-09:41:38.882278801] msec_range[1] 2000.000000 - 5000.000000 : 1 [20090728-09:41:38.884859715] msec_range[2] 1000.000000 - 2000.000000 : 7 [20090728-09:41:38.886959415] msec_range[3] 500.000000 - 1000.000000 : 13 [20090728-09:41:38.889138811] msec_range[4] 200.000000 - 500.000000 : 585 [20090728-09:41:38.891313598] msec_range[5] 100.000000 - 200.000000 : 76 [20090728-09:41:38.893497260] msec_range[6] 50.000000 - 100.000000 : 36 [20090728-09:41:38.895523506] msec_range[7] 20.000000 - 50.000000 : 40 [20090728-09:41:38.897688137] msec_range[8] 10.000000 - 20.000000 : 47 [20090728-09:41:38.899680110] msec_range[9] 5.000000 - 10.000000 : 211 [20090728-09:41:38.901845483] msec_range[10] 2.000000 - 5.000000 : 919 [20090728-09:41:38.903891290] msec_range[11] 1.000000 - 2.000000 : 705 [20090728-09:41:38.906073866] msec_range[12] 0.500000 - 1.000000 : 1155 [20090728-09:41:38.908179345] msec_range[13] 0.200000 - 0.500000 : 4396 [20090728-09:41:38.910337480] msec_range[14] 0.100000 - 0.200000 : 15491 [20090728-09:41:38.912362657] msec_range[15] 0.050000 - 0.100000 : 34294 [20090728-09:41:38.914418859] msec_range[16] 0.020000 - 0.050000 : 861365 [20090728-09:41:38.916538370] msec_range[17] 0.010000 - 0.020000 : 2214474 [20090728-09:41:38.918916125] msec_range[18] 0.000000 - 0.010000 : 905 [20090728-09:41:38.921510294] [20090728-09:41:38.923926125] [ lseek] 0.000000 0.001283 2.670000 3134720 [20090728-09:41:38.926130569] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-09:41:38.928509353] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-09:41:38.930841917] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-09:41:38.933578972] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-09:41:38.935927711] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-09:41:38.938265620] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-09:41:38.940531731] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-09:41:38.942802850] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-09:41:38.945328873] msec_range[8] 10.000000 - 20.000000 : 0 [20090728-09:41:38.947594521] msec_range[9] 5.000000 - 10.000000 : 0 [20090728-09:41:38.949845144] msec_range[10] 2.000000 - 5.000000 : 1 [20090728-09:41:38.952221409] msec_range[11] 1.000000 - 2.000000 : 8 [20090728-09:41:38.954533641] msec_range[12] 0.500000 - 1.000000 : 6 [20090728-09:41:38.956901030] msec_range[13] 0.200000 - 0.500000 : 9 [20090728-09:41:38.959631038] msec_range[14] 0.100000 - 0.200000 : 21 [20090728-09:41:38.961868714] msec_range[15] 0.050000 - 0.100000 : 105 [20090728-09:41:38.964046188] msec_range[16] 0.020000 - 0.050000 : 687 [20090728-09:41:38.966222588] msec_range[17] 0.010000 - 0.020000 : 580 [20090728-09:41:38.968646527] msec_range[18] 0.000000 - 0.010000 : 3133303 [20090728-09:41:38.970960090] [20090728-09:41:38.973222084] [ close] 0.004000 0.007565 0.057000 2449 [20090728-09:41:38.975629996] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-09:41:38.980054202] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-09:41:38.982366221] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-09:41:38.984767063] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-09:41:38.986798254] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-09:41:38.988722774] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-09:41:38.990936925] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-09:41:38.993404950] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-09:41:38.995775541] msec_range[8] 10.000000 - 20.000000 : 0 [20090728-09:41:38.998227376] msec_range[9] 5.000000 - 10.000000 : 0 [20090728-09:41:39.000689469] msec_range[10] 2.000000 - 5.000000 : 0 [20090728-09:41:39.002829789] msec_range[11] 1.000000 - 2.000000 : 0 [20090728-09:41:39.005044854] msec_range[12] 0.500000 - 1.000000 : 0 [20090728-09:41:39.007120884] msec_range[13] 0.200000 - 0.500000 : 0 [20090728-09:41:39.009090756] msec_range[14] 0.100000 - 0.200000 : 0 [20090728-09:41:39.011075675] msec_range[15] 0.050000 - 0.100000 : 2 [20090728-09:41:39.013111349] msec_range[16] 0.020000 - 0.050000 : 6 [20090728-09:41:39.015131460] msec_range[17] 0.010000 - 0.020000 : 139 [20090728-09:41:39.017084140] msec_range[18] 0.000000 - 0.010000 : 2302 [20090728-09:41:39.019188129] [20090728-09:41:39.021358591] [20090728-09:41:39.023574779] [20090728-09:41:39.025611515] [20090728-09:41:39.027783426] 1.4% User Time [20090728-09:41:39.029757443] 86.1% System Time [20090728-09:41:39.031693508] 87.5% CPU Utilization [20090728-09:41:39.033579153] Profilers reporting [20090728-09:41:39.194934550] Profilers postprocessing [20090728-09:41:39.465032549] Processing File : iostat.001 [20090728-09:41:39.467375716] Discovered iostat_interval=[5] [20090728-09:41:40.280386780] Processing Directory : sar.breakout.001 [20090728-09:41:40.282554402] Discovered sar_interval=[5] [20090728-09:41:40.469256483] Processing File : mpstat.001 [20090728-09:41:40.471601085] Discovered mpstat_interval=[5] [20090728-09:41:42.041317929] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-07-28_0851/btrfsexp-7-24' [20090728-09:41:47.583980063] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090728-09:41:51.298009830] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090728-09:41:51.454481065] ONLY : Command [run random_writes__threads_0016 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb num_threads=16] found for me [20090728-09:41:51.508237855] PROCESSING COMMAND : 'run random_writes__threads_0016 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb num_threads=16' [20090728-09:41:51.557661982] new log requested [20090728-09:41:51.600074718] Running command ffsb [20090728-09:42:02.786582865] 07/28/2009-09:42:02 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb Succeeded [20090728-09:42:02.797421229] Importing argument : num_threads=16 [20090728-09:42:02.826409440] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090728-09:42:02.907496518] FFSB version 6.0-RC2.1 started [20090728-09:42:02.909748166] [20090728-09:42:02.974533560] benchmark time = 300 [20090728-09:42:02.976758306] ThreadGroup 0 [20090728-09:42:02.979019722] ================ [20090728-09:42:02.981133106] num_threads = 16 [20090728-09:42:02.983203822] [20090728-09:42:02.985298831] read_random = off [20090728-09:42:02.987615283] read_size = 0 (0B) [20090728-09:42:02.989778778] read_blocksize = 0 (0B) [20090728-09:42:02.991898929] read_skip = off [20090728-09:42:02.993818660] read_skipsize = 0 (0B) [20090728-09:42:02.995795144] [20090728-09:42:02.997714252] write_random = on [20090728-09:42:02.999669864] write_size = 5242880 (5MB) [20090728-09:42:03.001558512] fsync_file = 0 [20090728-09:42:03.003503330] write_blocksize = 4096 (4KB) [20090728-09:42:03.005400339] wait time = 0 [20090728-09:42:03.007285586] [20090728-09:42:03.009194471] op weights [20090728-09:42:03.011131843] read = 0 (0.00%) [20090728-09:42:03.012992449] readall = 0 (0.00%) [20090728-09:42:03.014979769] write = 1 (100.00%) [20090728-09:42:03.016874650] create = 0 (0.00%) [20090728-09:42:03.018804603] append = 0 (0.00%) [20090728-09:42:03.020661363] delete = 0 (0.00%) [20090728-09:42:03.022676048] metaop = 0 (0.00%) [20090728-09:42:03.024637437] createdir = 0 (0.00%) [20090728-09:42:03.026717628] stat = 0 (0.00%) [20090728-09:42:03.028737871] writeall = 0 (0.00%) [20090728-09:42:03.030862861] writeall_fsync = 0 (0.00%) [20090728-09:42:03.032792212] open_close = 0 (0.00%) [20090728-09:42:03.034739406] write_fsync = 0 (0.00%) [20090728-09:42:03.036670429] create_fsync = 0 (0.00%) [20090728-09:42:03.038609952] append_fsync = 0 (0.00%) [20090728-09:42:03.040490984] [20090728-09:42:03.042443046] FileSystem /mnt/ffsb1 [20090728-09:42:03.044445406] ========== [20090728-09:42:03.046519021] num_dirs = 0 [20090728-09:42:03.048553967] starting files = 1024 [20090728-09:42:03.050603047] [20090728-09:42:03.052566242] min file size = 104857600 (100MB) [20090728-09:42:03.054573146] max file size = 104857600 (100MB) [20090728-09:42:03.056440271] directio = off [20090728-09:42:03.058622504] alignedio = on [20090728-09:42:03.060736164] bufferedio = off [20090728-09:42:03.062827884] [20090728-09:42:03.067476678] aging is off [20090728-09:42:03.070011222] current utilization = 4.94% [20090728-09:42:03.072034115] [20090728-09:42:03.074272066] creating new fileset /mnt/ffsb1 [20090728-09:55:18.281002498] fs setup took 794 secs [20090728-09:55:20.241753674] Syncing()...2 sec [20090728-09:55:20.244694321] Starting Actual Benchmark At: Tue Jul 28 09:55:20 2009 [20090728-09:55:20.349699083] [20090728-10:00:33.124207915] Syncing()...6 sec [20090728-10:00:33.145575721] FFSB benchmark finished at: Tue Jul 28 10:00:32 2009 [20090728-10:00:33.148195713] [20090728-10:00:33.150823992] Results: [20090728-10:00:33.185723922] Benchmark took 312.73 sec [20090728-10:00:33.187831167] [20090728-10:00:33.190026099] Total Results [20090728-10:00:33.207928519] =============== [20090728-10:00:33.210342494] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090728-10:00:33.212892495] ======= ============ ========= ======= =========== ========== [20090728-10:00:33.215156287] write : 3107840 9937.66 100.000% 100.000% 38.8MB/sec [20090728-10:00:33.217606270] - [20090728-10:00:33.220056436] 9937.66 Transactions per Second [20090728-10:00:33.222542373] [20090728-10:00:33.224870199] Throughput Results [20090728-10:00:33.240324296] =================== [20090728-10:00:33.242998651] Write Throughput: 38.8MB/sec [20090728-10:00:33.245226381] [20090728-10:00:33.247623677] System Call Latency statistics in millisecs [20090728-10:00:33.249919470] ===== [20090728-10:00:33.252208284] Min Avg Max Total Calls [20090728-10:00:33.254459460] ======== ======== ======== ============ [20090728-10:00:33.256658793] [ open] 0.008000 0.259909 404.204010 2428 [20090728-10:00:33.258948247] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-10:00:33.261125905] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-10:00:33.263300714] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-10:00:33.265405093] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-10:00:33.267519104] msec_range[4] 200.000000 - 500.000000 : 1 [20090728-10:00:33.269608278] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-10:00:33.271758272] msec_range[6] 50.000000 - 100.000000 : 1 [20090728-10:00:33.273872014] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-10:00:33.276028408] msec_range[8] 10.000000 - 20.000000 : 2 [20090728-10:00:33.278102986] msec_range[9] 5.000000 - 10.000000 : 2 [20090728-10:00:33.280316951] msec_range[10] 2.000000 - 5.000000 : 4 [20090728-10:00:33.282442023] msec_range[11] 1.000000 - 2.000000 : 3 [20090728-10:00:33.284546489] msec_range[12] 0.500000 - 1.000000 : 7 [20090728-10:00:33.286666548] msec_range[13] 0.200000 - 0.500000 : 22 [20090728-10:00:33.288725934] msec_range[14] 0.100000 - 0.200000 : 136 [20090728-10:00:33.290742761] msec_range[15] 0.050000 - 0.100000 : 161 [20090728-10:00:33.292941007] msec_range[16] 0.020000 - 0.050000 : 2051 [20090728-10:00:33.294970947] msec_range[17] 0.010000 - 0.020000 : 33 [20090728-10:00:33.297070911] msec_range[18] 0.000000 - 0.010000 : 5 [20090728-10:00:33.299167885] [20090728-10:00:33.301296312] [ write] 0.009000 1.518884 18001.083984 3107840 [20090728-10:00:33.303392975] msec_range[0] 5000.000000 - 10000.000000 : 200 [20090728-10:00:33.305572682] msec_range[1] 2000.000000 - 5000.000000 : 153 [20090728-10:00:33.307661521] msec_range[2] 1000.000000 - 2000.000000 : 287 [20090728-10:00:33.309821752] msec_range[3] 500.000000 - 1000.000000 : 813 [20090728-10:00:33.311944748] msec_range[4] 200.000000 - 500.000000 : 577 [20090728-10:00:33.314088981] msec_range[5] 100.000000 - 200.000000 : 301 [20090728-10:00:33.316226965] msec_range[6] 50.000000 - 100.000000 : 913 [20090728-10:00:33.318367768] msec_range[7] 20.000000 - 50.000000 : 1019 [20090728-10:00:33.320419073] msec_range[8] 10.000000 - 20.000000 : 774 [20090728-10:00:33.322549061] msec_range[9] 5.000000 - 10.000000 : 1158 [20090728-10:00:33.324620578] msec_range[10] 2.000000 - 5.000000 : 2113 [20090728-10:00:33.326771460] msec_range[11] 1.000000 - 2.000000 : 11065 [20090728-10:00:33.328785792] msec_range[12] 0.500000 - 1.000000 : 75522 [20090728-10:00:33.330882303] msec_range[13] 0.200000 - 0.500000 : 215437 [20090728-10:00:33.332916409] msec_range[14] 0.100000 - 0.200000 : 277866 [20090728-10:00:33.334977497] msec_range[15] 0.050000 - 0.100000 : 332650 [20090728-10:00:33.337010516] msec_range[16] 0.020000 - 0.050000 : 1561877 [20090728-10:00:33.339131410] msec_range[17] 0.010000 - 0.020000 : 624982 [20090728-10:00:33.341188203] msec_range[18] 0.000000 - 0.010000 : 33 [20090728-10:00:33.343306956] [20090728-10:00:33.345329712] [ lseek] 0.000000 0.046870 15448.465820 3107840 [20090728-10:00:33.347445545] msec_range[0] 5000.000000 - 10000.000000 : 7 [20090728-10:00:33.349485725] msec_range[1] 2000.000000 - 5000.000000 : 7 [20090728-10:00:33.351756020] msec_range[2] 1000.000000 - 2000.000000 : 5 [20090728-10:00:33.353805625] msec_range[3] 500.000000 - 1000.000000 : 5 [20090728-10:00:33.355969999] msec_range[4] 200.000000 - 500.000000 : 6 [20090728-10:00:33.358161231] msec_range[5] 100.000000 - 200.000000 : 9 [20090728-10:00:33.360309258] msec_range[6] 50.000000 - 100.000000 : 18 [20090728-10:00:33.362401769] msec_range[7] 20.000000 - 50.000000 : 15 [20090728-10:00:33.364621512] msec_range[8] 10.000000 - 20.000000 : 11 [20090728-10:00:33.366783728] msec_range[9] 5.000000 - 10.000000 : 24 [20090728-10:00:33.369004195] msec_range[10] 2.000000 - 5.000000 : 41 [20090728-10:00:33.371119525] msec_range[11] 1.000000 - 2.000000 : 47 [20090728-10:00:33.373490326] msec_range[12] 0.500000 - 1.000000 : 317 [20090728-10:00:33.375963531] msec_range[13] 0.200000 - 0.500000 : 1747 [20090728-10:00:33.378577062] msec_range[14] 0.100000 - 0.200000 : 1956 [20090728-10:00:33.381206389] msec_range[15] 0.050000 - 0.100000 : 2243 [20090728-10:00:33.383793143] msec_range[16] 0.020000 - 0.050000 : 8626 [20090728-10:00:33.386203104] msec_range[17] 0.010000 - 0.020000 : 6267 [20090728-10:00:33.388656860] msec_range[18] 0.000000 - 0.010000 : 3086485 [20090728-10:00:33.391119840] [20090728-10:00:33.393417772] [ close] 0.004000 0.011306 4.827000 2428 [20090728-10:00:33.395777609] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-10:00:33.398182837] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-10:00:33.400431934] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-10:00:33.402931738] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-10:00:33.405444457] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-10:00:33.407869669] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-10:00:33.410171722] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-10:00:33.412630298] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-10:00:33.414858681] msec_range[8] 10.000000 - 20.000000 : 0 [20090728-10:00:33.417121549] msec_range[9] 5.000000 - 10.000000 : 0 [20090728-10:00:33.419336328] msec_range[10] 2.000000 - 5.000000 : 1 [20090728-10:00:33.421558725] msec_range[11] 1.000000 - 2.000000 : 0 [20090728-10:00:33.423675532] msec_range[12] 0.500000 - 1.000000 : 0 [20090728-10:00:33.425904878] msec_range[13] 0.200000 - 0.500000 : 0 [20090728-10:00:33.428284901] msec_range[14] 0.100000 - 0.200000 : 1 [20090728-10:00:33.430600152] msec_range[15] 0.050000 - 0.100000 : 3 [20090728-10:00:33.432924076] msec_range[16] 0.020000 - 0.050000 : 15 [20090728-10:00:33.435128543] msec_range[17] 0.010000 - 0.020000 : 807 [20090728-10:00:33.437361466] msec_range[18] 0.000000 - 0.010000 : 1601 [20090728-10:00:33.439516687] [20090728-10:00:33.441873526] [20090728-10:00:33.444169591] [20090728-10:00:33.446431250] [20090728-10:00:33.448774886] 2.5% User Time [20090728-10:00:33.451131468] 325.0% System Time [20090728-10:00:33.453479295] 327.4% CPU Utilization [20090728-10:00:33.482543171] Profilers reporting [20090728-10:00:33.825987027] Profilers postprocessing [20090728-10:00:34.099920280] Processing File : iostat.001 [20090728-10:00:34.102440860] Discovered iostat_interval=[5] [20090728-10:00:34.926033400] Processing Directory : sar.breakout.001 [20090728-10:00:34.928187409] Discovered sar_interval=[5] [20090728-10:00:35.116066877] Processing File : mpstat.001 [20090728-10:00:35.118413329] Discovered mpstat_interval=[5] [20090728-10:00:36.818286325] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-07-28_0851/btrfsexp-7-24' [20090728-10:00:42.142013960] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090728-10:00:45.867361758] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090728-10:00:46.030545366] ONLY : Command [run random_writes__threads_0128 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb num_threads=128] found for me [20090728-10:00:46.084276716] PROCESSING COMMAND : 'run random_writes__threads_0128 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb num_threads=128' [20090728-10:00:46.133989143] new log requested [20090728-10:00:46.176866710] Running command ffsb [20090728-10:00:57.628621073] 07/28/2009-10:00:57 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb Succeeded [20090728-10:00:57.640059683] Importing argument : num_threads=128 [20090728-10:00:57.668890487] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090728-10:00:57.761114653] FFSB version 6.0-RC2.1 started [20090728-10:00:57.763267197] [20090728-10:00:58.295825848] benchmark time = 300 [20090728-10:00:58.297914322] ThreadGroup 0 [20090728-10:00:58.299936690] ================ [20090728-10:00:58.302132522] num_threads = 128 [20090728-10:00:58.304429211] [20090728-10:00:58.306662084] read_random = off [20090728-10:00:58.309056012] read_size = 0 (0B) [20090728-10:00:58.311214587] read_blocksize = 0 (0B) [20090728-10:00:58.313372389] read_skip = off [20090728-10:00:58.315516141] read_skipsize = 0 (0B) [20090728-10:00:58.317423090] [20090728-10:00:58.319338039] write_random = on [20090728-10:00:58.321284206] write_size = 5242880 (5MB) [20090728-10:00:58.323502933] fsync_file = 0 [20090728-10:00:58.325367424] write_blocksize = 4096 (4KB) [20090728-10:00:58.327349289] wait time = 0 [20090728-10:00:58.329246637] [20090728-10:00:58.331245057] op weights [20090728-10:00:58.333135727] read = 0 (0.00%) [20090728-10:00:58.335077921] readall = 0 (0.00%) [20090728-10:00:58.337030634] write = 1 (100.00%) [20090728-10:00:58.339139501] create = 0 (0.00%) [20090728-10:00:58.341021144] append = 0 (0.00%) [20090728-10:00:58.342958489] delete = 0 (0.00%) [20090728-10:00:58.344842676] metaop = 0 (0.00%) [20090728-10:00:58.346845782] createdir = 0 (0.00%) [20090728-10:00:58.348792377] stat = 0 (0.00%) [20090728-10:00:58.350907554] writeall = 0 (0.00%) [20090728-10:00:58.353359748] writeall_fsync = 0 (0.00%) [20090728-10:00:58.355426495] open_close = 0 (0.00%) [20090728-10:00:58.357285747] write_fsync = 0 (0.00%) [20090728-10:00:58.359261748] create_fsync = 0 (0.00%) [20090728-10:00:58.361457215] append_fsync = 0 (0.00%) [20090728-10:00:58.363464696] [20090728-10:00:58.365321756] FileSystem /mnt/ffsb1 [20090728-10:00:58.367275612] ========== [20090728-10:00:58.369538455] num_dirs = 0 [20090728-10:00:58.371566057] starting files = 1024 [20090728-10:00:58.373421585] [20090728-10:00:58.375361793] min file size = 104857600 (100MB) [20090728-10:00:58.377344913] max file size = 104857600 (100MB) [20090728-10:00:58.379259045] directio = off [20090728-10:00:58.381273894] alignedio = on [20090728-10:00:58.383221790] bufferedio = off [20090728-10:00:58.385551401] [20090728-10:00:58.387431543] aging is off [20090728-10:00:58.389444972] current utilization = 4.99% [20090728-10:00:58.391638931] [20090728-10:00:58.393674117] creating new fileset /mnt/ffsb1 [20090728-10:16:06.109328971] fs setup took 907 secs [20090728-10:16:08.168365731] Syncing()...2 sec [20090728-10:16:08.173526342] Starting Actual Benchmark At: Tue Jul 28 10:16:08 2009 [20090728-10:16:08.333037890] [20090728-10:21:30.582671783] Syncing()...12 sec [20090728-10:21:30.617089733] FFSB benchmark finished at: Tue Jul 28 10:21:30 2009 [20090728-10:21:30.619744869] [20090728-10:21:30.622370444] Results: [20090728-10:21:30.655272086] Benchmark took 322.27 sec [20090728-10:21:30.657810000] [20090728-10:21:30.660207046] Total Results [20090728-10:21:30.675365760] =============== [20090728-10:21:30.677547465] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090728-10:21:30.679662279] ======= ============ ========= ======= =========== ========== [20090728-10:21:30.681874991] write : 2963200 9194.74 100.000% 100.000% 35.9MB/sec [20090728-10:21:30.684176917] - [20090728-10:21:30.686271599] 9194.74 Transactions per Second [20090728-10:21:30.688400260] [20090728-10:21:30.690459576] Throughput Results [20090728-10:21:30.705228519] =================== [20090728-10:21:30.707484421] Write Throughput: 35.9MB/sec [20090728-10:21:30.709498193] [20090728-10:21:30.711634266] System Call Latency statistics in millisecs [20090728-10:21:30.714046317] ===== [20090728-10:21:30.716227545] Min Avg Max Total Calls [20090728-10:21:30.718668836] ======== ======== ======== ============ [20090728-10:21:30.720927998] [ open] 0.008000 0.083172 34.002998 2315 [20090728-10:21:30.723265359] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-10:21:30.725459564] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-10:21:30.727683400] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-10:21:30.729845971] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-10:21:30.731927450] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-10:21:30.734056186] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-10:21:30.736201373] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-10:21:30.738293234] msec_range[7] 20.000000 - 50.000000 : 2 [20090728-10:21:30.740416070] msec_range[8] 10.000000 - 20.000000 : 0 [20090728-10:21:30.742490863] msec_range[9] 5.000000 - 10.000000 : 2 [20090728-10:21:30.744632718] msec_range[10] 2.000000 - 5.000000 : 2 [20090728-10:21:30.746741336] msec_range[11] 1.000000 - 2.000000 : 3 [20090728-10:21:30.748820074] msec_range[12] 0.500000 - 1.000000 : 5 [20090728-10:21:30.750895035] msec_range[13] 0.200000 - 0.500000 : 18 [20090728-10:21:30.753043599] msec_range[14] 0.100000 - 0.200000 : 147 [20090728-10:21:30.755083866] msec_range[15] 0.050000 - 0.100000 : 158 [20090728-10:21:30.757238881] msec_range[16] 0.020000 - 0.050000 : 1866 [20090728-10:21:30.759348902] msec_range[17] 0.010000 - 0.020000 : 99 [20090728-10:21:30.761420791] msec_range[18] 0.000000 - 0.010000 : 13 [20090728-10:21:30.763470734] [20090728-10:21:30.765583473] [ write] 0.008000 11.952721 44012.347656 2963200 [20090728-10:21:30.767656711] msec_range[0] 5000.000000 - 10000.000000 : 924 [20090728-10:21:30.769809459] msec_range[1] 2000.000000 - 5000.000000 : 1036 [20090728-10:21:30.771842691] msec_range[2] 1000.000000 - 2000.000000 : 1398 [20090728-10:21:30.773869544] msec_range[3] 500.000000 - 1000.000000 : 2744 [20090728-10:21:30.775926969] msec_range[4] 200.000000 - 500.000000 : 1495 [20090728-10:21:30.778048827] msec_range[5] 100.000000 - 200.000000 : 948 [20090728-10:21:30.780040216] msec_range[6] 50.000000 - 100.000000 : 1044 [20090728-10:21:30.782156654] msec_range[7] 20.000000 - 50.000000 : 1429 [20090728-10:21:30.784501527] msec_range[8] 10.000000 - 20.000000 : 546 [20090728-10:21:30.786754886] msec_range[9] 5.000000 - 10.000000 : 837 [20090728-10:21:30.789064063] msec_range[10] 2.000000 - 5.000000 : 1523 [20090728-10:21:30.791384059] msec_range[11] 1.000000 - 2.000000 : 13580 [20090728-10:21:30.793620947] msec_range[12] 0.500000 - 1.000000 : 129157 [20090728-10:21:30.795677410] msec_range[13] 0.200000 - 0.500000 : 351591 [20090728-10:21:30.797827392] msec_range[14] 0.100000 - 0.200000 : 326861 [20090728-10:21:30.800018527] msec_range[15] 0.050000 - 0.100000 : 308024 [20090728-10:21:30.802206821] msec_range[16] 0.020000 - 0.050000 : 1259889 [20090728-10:21:30.804292748] msec_range[17] 0.010000 - 0.020000 : 558876 [20090728-10:21:30.806460766] msec_range[18] 0.000000 - 0.010000 : 24 [20090728-10:21:30.808618564] [20090728-10:21:30.810878678] [ lseek] 0.000000 1.341275 35975.160156 2963200 [20090728-10:21:30.812862910] msec_range[0] 5000.000000 - 10000.000000 : 97 [20090728-10:21:30.815764975] msec_range[1] 2000.000000 - 5000.000000 : 71 [20090728-10:21:30.819237641] msec_range[2] 1000.000000 - 2000.000000 : 84 [20090728-10:21:30.821748642] msec_range[3] 500.000000 - 1000.000000 : 153 [20090728-10:21:30.824486243] msec_range[4] 200.000000 - 500.000000 : 84 [20090728-10:21:30.826838948] msec_range[5] 100.000000 - 200.000000 : 32 [20090728-10:21:30.828997461] msec_range[6] 50.000000 - 100.000000 : 47 [20090728-10:21:30.831569743] msec_range[7] 20.000000 - 50.000000 : 45 [20090728-10:21:30.833740177] msec_range[8] 10.000000 - 20.000000 : 29 [20090728-10:21:30.835890788] msec_range[9] 5.000000 - 10.000000 : 59 [20090728-10:21:30.837974277] msec_range[10] 2.000000 - 5.000000 : 51 [20090728-10:21:30.840150680] msec_range[11] 1.000000 - 2.000000 : 82 [20090728-10:21:30.842324436] msec_range[12] 0.500000 - 1.000000 : 1752 [20090728-10:21:30.844582076] msec_range[13] 0.200000 - 0.500000 : 14112 [20090728-10:21:30.847668305] msec_range[14] 0.100000 - 0.200000 : 17543 [20090728-10:21:30.849915863] msec_range[15] 0.050000 - 0.100000 : 15833 [20090728-10:21:30.852060338] msec_range[16] 0.020000 - 0.050000 : 43115 [20090728-10:21:30.854269850] msec_range[17] 0.010000 - 0.020000 : 12821 [20090728-10:21:30.856598520] msec_range[18] 0.000000 - 0.010000 : 2857028 [20090728-10:21:30.858690103] [20090728-10:21:30.860778747] [ close] 0.003000 0.012307 7.563000 2315 [20090728-10:21:30.862874251] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-10:21:30.864999212] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-10:21:30.867110770] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-10:21:30.869306121] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-10:21:30.871821103] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-10:21:30.874165274] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-10:21:30.876736513] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-10:21:30.878979387] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-10:21:30.881338255] msec_range[8] 10.000000 - 20.000000 : 0 [20090728-10:21:30.883639009] msec_range[9] 5.000000 - 10.000000 : 1 [20090728-10:21:30.886045284] msec_range[10] 2.000000 - 5.000000 : 0 [20090728-10:21:30.888160182] msec_range[11] 1.000000 - 2.000000 : 0 [20090728-10:21:30.890342269] msec_range[12] 0.500000 - 1.000000 : 0 [20090728-10:21:30.892525768] msec_range[13] 0.200000 - 0.500000 : 1 [20090728-10:21:30.894809077] msec_range[14] 0.100000 - 0.200000 : 0 [20090728-10:21:30.897117309] msec_range[15] 0.050000 - 0.100000 : 2 [20090728-10:21:30.899510510] msec_range[16] 0.020000 - 0.050000 : 7 [20090728-10:21:30.901918913] msec_range[17] 0.010000 - 0.020000 : 672 [20090728-10:21:30.904098651] msec_range[18] 0.000000 - 0.010000 : 1632 [20090728-10:21:30.906311640] [20090728-10:21:30.908379790] [20090728-10:21:30.911032668] [20090728-10:21:30.913245602] [20090728-10:21:30.915510169] 2.0% User Time [20090728-10:21:30.917790210] 363.4% System Time [20090728-10:21:30.920100281] 365.4% CPU Utilization [20090728-10:21:30.923510049] Profilers reporting [20090728-10:21:31.258987852] Profilers postprocessing [20090728-10:21:31.517915624] Processing File : iostat.001 [20090728-10:21:31.520531742] Discovered iostat_interval=[5] [20090728-10:21:32.332559567] Processing Directory : sar.breakout.001 [20090728-10:21:32.334688448] Discovered sar_interval=[5] [20090728-10:21:32.526115800] Processing File : mpstat.001 [20090728-10:21:32.528338991] Discovered mpstat_interval=[5] [20090728-10:21:34.062814178] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-07-28_0851/btrfsexp-7-24' [20090728-10:21:39.730283904] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090728-10:21:43.469498201] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090728-10:21:43.635290912] ONLY : Command [run random_writes_odirect__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb num_threads=1] found for me [20090728-10:21:43.688702419] PROCESSING COMMAND : 'run random_writes_odirect__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb num_threads=1' [20090728-10:21:43.738698910] new log requested [20090728-10:21:43.778317939] Running command ffsb [20090728-10:21:54.931897309] 07/28/2009-10:21:54 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb Succeeded [20090728-10:21:54.942806621] Importing argument : num_threads=1 [20090728-10:21:54.971671293] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090728-10:21:55.056044282] FFSB version 6.0-RC2.1 started [20090728-10:21:55.058004571] [20090728-10:21:55.060286713] benchmark time = 300 [20090728-10:21:55.062525355] ThreadGroup 0 [20090728-10:21:55.064715165] ================ [20090728-10:21:55.066766290] num_threads = 1 [20090728-10:21:55.069004892] [20090728-10:21:55.071460466] read_random = off [20090728-10:21:55.073692758] read_size = 0 (0B) [20090728-10:21:55.075850643] read_blocksize = 0 (0B) [20090728-10:21:55.077765207] read_skip = off [20090728-10:21:55.079748673] read_skipsize = 0 (0B) [20090728-10:21:55.081667082] [20090728-10:21:55.083732826] write_random = on [20090728-10:21:55.085662896] write_size = 5242880 (5MB) [20090728-10:21:55.087647533] fsync_file = 0 [20090728-10:21:55.089545022] write_blocksize = 4096 (4KB) [20090728-10:21:55.091526903] wait time = 0 [20090728-10:21:55.093412566] [20090728-10:21:55.095388927] op weights [20090728-10:21:55.097291222] read = 0 (0.00%) [20090728-10:21:55.099288345] readall = 0 (0.00%) [20090728-10:21:55.101185501] write = 1 (100.00%) [20090728-10:21:55.103133287] create = 0 (0.00%) [20090728-10:21:55.104997230] append = 0 (0.00%) [20090728-10:21:55.106967788] delete = 0 (0.00%) [20090728-10:21:55.108870014] metaop = 0 (0.00%) [20090728-10:21:55.110824610] createdir = 0 (0.00%) [20090728-10:21:55.112706925] stat = 0 (0.00%) [20090728-10:21:55.114683607] writeall = 0 (0.00%) [20090728-10:21:55.116590436] writeall_fsync = 0 (0.00%) [20090728-10:21:55.118526188] open_close = 0 (0.00%) [20090728-10:21:55.120347993] write_fsync = 0 (0.00%) [20090728-10:21:55.122341536] create_fsync = 0 (0.00%) [20090728-10:21:55.124349709] append_fsync = 0 (0.00%) [20090728-10:21:55.126415018] [20090728-10:21:55.128506121] FileSystem /mnt/ffsb1 [20090728-10:21:55.130613387] ========== [20090728-10:21:55.132522021] num_dirs = 0 [20090728-10:21:55.134503781] starting files = 1024 [20090728-10:21:55.136454681] [20090728-10:21:55.138448699] min file size = 104857600 (100MB) [20090728-10:21:55.140358960] max file size = 104857600 (100MB) [20090728-10:21:55.142311368] directio = on [20090728-10:21:55.144237790] alignedio = on [20090728-10:21:55.146209706] bufferedio = off [20090728-10:21:55.148095915] [20090728-10:21:55.150065053] aging is off [20090728-10:21:55.151976777] current utilization = 4.98% [20090728-10:21:55.153957519] [20090728-10:21:55.155839929] creating new fileset /mnt/ffsb1 [20090728-10:37:29.478579776] fs setup took 934 secs [20090728-10:37:31.145063123] Syncing()...1 sec [20090728-10:37:31.148087731] Starting Actual Benchmark At: Tue Jul 28 10:37:31 2009 [20090728-10:37:31.231977376] [20090728-10:42:32.057334565] Syncing()...0 sec [20090728-10:42:32.060138795] FFSB benchmark finished at: Tue Jul 28 10:42:32 2009 [20090728-10:42:32.062714988] [20090728-10:42:32.065357829] Results: [20090728-10:42:32.080578276] Benchmark took 300.91 sec [20090728-10:42:32.082767559] [20090728-10:42:32.084907903] Total Results [20090728-10:42:32.104785510] =============== [20090728-10:42:32.107203179] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090728-10:42:32.109701172] ======= ============ ========= ======= =========== ========== [20090728-10:42:32.112078140] write : 578560 1922.68 100.000% 100.000% 7.51MB/sec [20090728-10:42:32.114378672] - [20090728-10:42:32.116422682] 1922.68 Transactions per Second [20090728-10:42:32.118497148] [20090728-10:42:32.120515901] Throughput Results [20090728-10:42:32.135644238] =================== [20090728-10:42:32.137945539] Write Throughput: 7.51MB/sec [20090728-10:42:32.139896392] [20090728-10:42:32.142156897] System Call Latency statistics in millisecs [20090728-10:42:32.144431141] ===== [20090728-10:42:32.146655712] Min Avg Max Total Calls [20090728-10:42:32.149069775] ======== ======== ======== ============ [20090728-10:42:32.151214918] [ open] 0.013000 0.033365 0.523000 452 [20090728-10:42:32.153671767] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-10:42:32.155950574] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-10:42:32.158219722] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-10:42:32.160410420] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-10:42:32.162528678] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-10:42:32.164515466] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-10:42:32.166526300] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-10:42:32.168508102] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-10:42:32.171945323] msec_range[8] 10.000000 - 20.000000 : 0 [20090728-10:42:32.174066264] msec_range[9] 5.000000 - 10.000000 : 0 [20090728-10:42:32.176270528] msec_range[10] 2.000000 - 5.000000 : 0 [20090728-10:42:32.178519247] msec_range[11] 1.000000 - 2.000000 : 0 [20090728-10:42:32.180552048] msec_range[12] 0.500000 - 1.000000 : 1 [20090728-10:42:32.182541569] msec_range[13] 0.200000 - 0.500000 : 1 [20090728-10:42:32.184572205] msec_range[14] 0.100000 - 0.200000 : 0 [20090728-10:42:32.186703791] msec_range[15] 0.050000 - 0.100000 : 18 [20090728-10:42:32.188712353] msec_range[16] 0.020000 - 0.050000 : 266 [20090728-10:42:32.190792317] msec_range[17] 0.010000 - 0.020000 : 166 [20090728-10:42:32.192901500] msec_range[18] 0.000000 - 0.010000 : 0 [20090728-10:42:32.195076910] [20090728-10:42:32.197025946] [ write] 0.339000 0.517252 102.459999 578560 [20090728-10:42:32.199076787] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-10:42:32.201149158] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-10:42:32.203213285] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-10:42:32.205140911] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-10:42:32.207230224] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-10:42:32.209212829] msec_range[5] 100.000000 - 200.000000 : 1 [20090728-10:42:32.211242462] msec_range[6] 50.000000 - 100.000000 : 7 [20090728-10:42:32.213184640] msec_range[7] 20.000000 - 50.000000 : 38 [20090728-10:42:32.215169870] msec_range[8] 10.000000 - 20.000000 : 77 [20090728-10:42:32.217130505] msec_range[9] 5.000000 - 10.000000 : 124 [20090728-10:42:32.219126516] msec_range[10] 2.000000 - 5.000000 : 124 [20090728-10:42:32.221088129] msec_range[11] 1.000000 - 2.000000 : 526 [20090728-10:42:32.223084310] msec_range[12] 0.500000 - 1.000000 : 394606 [20090728-10:42:32.225159639] msec_range[13] 0.200000 - 0.500000 : 183057 [20090728-10:42:32.227211297] msec_range[14] 0.100000 - 0.200000 : 0 [20090728-10:42:32.229121410] msec_range[15] 0.050000 - 0.100000 : 0 [20090728-10:42:32.231091156] msec_range[16] 0.020000 - 0.050000 : 0 [20090728-10:42:32.233113354] msec_range[17] 0.010000 - 0.020000 : 0 [20090728-10:42:32.235260111] msec_range[18] 0.000000 - 0.010000 : 0 [20090728-10:42:32.237280003] [20090728-10:42:32.239320900] [ lseek] 0.000000 0.001437 0.042000 578560 [20090728-10:42:32.241414108] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-10:42:32.243421963] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-10:42:32.245616122] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-10:42:32.247803844] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-10:42:32.249882356] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-10:42:32.251887907] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-10:42:32.254003700] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-10:42:32.256230749] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-10:42:32.258392382] msec_range[8] 10.000000 - 20.000000 : 0 [20090728-10:42:32.260632628] msec_range[9] 5.000000 - 10.000000 : 0 [20090728-10:42:32.262830392] msec_range[10] 2.000000 - 5.000000 : 0 [20090728-10:42:32.265073834] msec_range[11] 1.000000 - 2.000000 : 0 [20090728-10:42:32.267394117] msec_range[12] 0.500000 - 1.000000 : 0 [20090728-10:42:32.269915244] msec_range[13] 0.200000 - 0.500000 : 0 [20090728-10:42:32.272560950] msec_range[14] 0.100000 - 0.200000 : 0 [20090728-10:42:32.275056004] msec_range[15] 0.050000 - 0.100000 : 0 [20090728-10:42:32.277888795] msec_range[16] 0.020000 - 0.050000 : 3 [20090728-10:42:32.280481037] msec_range[17] 0.010000 - 0.020000 : 38 [20090728-10:42:32.282901545] msec_range[18] 0.000000 - 0.010000 : 578519 [20090728-10:42:32.285342284] [20090728-10:42:32.287742462] [ close] 0.003000 0.005131 0.011000 452 [20090728-10:42:32.290092774] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-10:42:32.292485677] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-10:42:32.294748751] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-10:42:32.297308063] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-10:42:32.299791502] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-10:42:32.302153127] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-10:42:32.304669440] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-10:42:32.307039264] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-10:42:32.309960946] msec_range[8] 10.000000 - 20.000000 : 0 [20090728-10:42:32.312415461] msec_range[9] 5.000000 - 10.000000 : 0 [20090728-10:42:32.314718602] msec_range[10] 2.000000 - 5.000000 : 0 [20090728-10:42:32.317312574] msec_range[11] 1.000000 - 2.000000 : 0 [20090728-10:42:32.319470783] msec_range[12] 0.500000 - 1.000000 : 0 [20090728-10:42:32.321616673] msec_range[13] 0.200000 - 0.500000 : 0 [20090728-10:42:32.324152914] msec_range[14] 0.100000 - 0.200000 : 0 [20090728-10:42:32.326375790] msec_range[15] 0.050000 - 0.100000 : 0 [20090728-10:42:32.328385287] msec_range[16] 0.020000 - 0.050000 : 0 [20090728-10:42:32.330496274] msec_range[17] 0.010000 - 0.020000 : 1 [20090728-10:42:32.332981326] msec_range[18] 0.000000 - 0.010000 : 451 [20090728-10:42:32.335158099] [20090728-10:42:32.337042197] [20090728-10:42:32.339480879] [20090728-10:42:32.341732747] [20090728-10:42:32.343827341] 0.5% User Time [20090728-10:42:32.345809914] 29.3% System Time [20090728-10:42:32.347963642] 29.9% CPU Utilization [20090728-10:42:32.349888289] Profilers reporting [20090728-10:42:32.531281434] Profilers postprocessing [20090728-10:42:32.787265181] Processing File : iostat.001 [20090728-10:42:32.789465112] Discovered iostat_interval=[5] [20090728-10:42:33.574432781] Processing Directory : sar.breakout.001 [20090728-10:42:33.576859562] Discovered sar_interval=[5] [20090728-10:42:33.746668210] Processing File : mpstat.001 [20090728-10:42:33.748948837] Discovered mpstat_interval=[5] [20090728-10:42:35.220821115] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-07-28_0851/btrfsexp-7-24' [20090728-10:42:40.505487288] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090728-10:42:42.890244183] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090728-10:42:43.039290255] ONLY : Command [run random_writes_odirect__threads_0016 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb num_threads=16] found for me [20090728-10:42:43.093032128] PROCESSING COMMAND : 'run random_writes_odirect__threads_0016 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb num_threads=16' [20090728-10:42:43.141425948] new log requested [20090728-10:42:43.171943521] Running command ffsb [20090728-10:42:54.367420398] 07/28/2009-10:42:54 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb Succeeded [20090728-10:42:54.378107180] Importing argument : num_threads=16 [20090728-10:42:54.407274635] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090728-10:42:54.492507959] FFSB version 6.0-RC2.1 started [20090728-10:42:54.494853233] [20090728-10:42:54.559715063] benchmark time = 300 [20090728-10:42:54.561965657] ThreadGroup 0 [20090728-10:42:54.564070558] ================ [20090728-10:42:54.566304533] num_threads = 16 [20090728-10:42:54.568733551] [20090728-10:42:54.570774969] read_random = off [20090728-10:42:54.573014082] read_size = 0 (0B) [20090728-10:42:54.575169489] read_blocksize = 0 (0B) [20090728-10:42:54.577272909] read_skip = off [20090728-10:42:54.579192755] read_skipsize = 0 (0B) [20090728-10:42:54.581145991] [20090728-10:42:54.583082416] write_random = on [20090728-10:42:54.585042771] write_size = 5242880 (5MB) [20090728-10:42:54.586960194] fsync_file = 0 [20090728-10:42:54.588906667] write_blocksize = 4096 (4KB) [20090728-10:42:54.590837928] wait time = 0 [20090728-10:42:54.592814952] [20090728-10:42:54.594726176] op weights [20090728-10:42:54.596671338] read = 0 (0.00%) [20090728-10:42:54.599767000] readall = 0 (0.00%) [20090728-10:42:54.601893995] write = 1 (100.00%) [20090728-10:42:54.603835297] create = 0 (0.00%) [20090728-10:42:54.605916834] append = 0 (0.00%) [20090728-10:42:54.607971818] delete = 0 (0.00%) [20090728-10:42:54.609936342] metaop = 0 (0.00%) [20090728-10:42:54.611931581] createdir = 0 (0.00%) [20090728-10:42:54.614029251] stat = 0 (0.00%) [20090728-10:42:54.616146301] writeall = 0 (0.00%) [20090728-10:42:54.618036982] writeall_fsync = 0 (0.00%) [20090728-10:42:54.619957840] open_close = 0 (0.00%) [20090728-10:42:54.621974546] write_fsync = 0 (0.00%) [20090728-10:42:54.623988445] create_fsync = 0 (0.00%) [20090728-10:42:54.625907504] append_fsync = 0 (0.00%) [20090728-10:42:54.627911821] [20090728-10:42:54.629827127] FileSystem /mnt/ffsb1 [20090728-10:42:54.631879305] ========== [20090728-10:42:54.633768092] num_dirs = 0 [20090728-10:42:54.635704531] starting files = 1024 [20090728-10:42:54.637616054] [20090728-10:42:54.639636318] min file size = 104857600 (100MB) [20090728-10:42:54.641515030] max file size = 104857600 (100MB) [20090728-10:42:54.643444652] directio = on [20090728-10:42:54.645331859] alignedio = on [20090728-10:42:54.647232783] bufferedio = off [20090728-10:42:54.649154612] [20090728-10:42:54.651114093] aging is off [20090728-10:42:54.653063066] current utilization = 4.58% [20090728-10:42:54.655033941] [20090728-10:42:54.656918827] creating new fileset /mnt/ffsb1 [20090728-10:49:28.595130106] fs setup took 393 secs [20090728-10:49:30.640568804] Syncing()...2 sec [20090728-10:49:30.643083771] Starting Actual Benchmark At: Tue Jul 28 10:49:30 2009 [20090728-10:49:30.747220426] [20090728-10:54:33.925732701] Syncing()...0 sec [20090728-10:54:33.928424004] FFSB benchmark finished at: Tue Jul 28 10:54:33 2009 [20090728-10:54:33.931172627] [20090728-10:54:33.933618451] Results: [20090728-10:54:33.948540877] Benchmark took 303.28 sec [20090728-10:54:33.950602189] [20090728-10:54:33.952895790] Total Results [20090728-10:54:33.967625237] =============== [20090728-10:54:33.969679277] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090728-10:54:33.972145548] ======= ============ ========= ======= =========== ========== [20090728-10:54:33.974292313] write : 1955840 6448.85 100.000% 100.000% 25.2MB/sec [20090728-10:54:33.976348526] - [20090728-10:54:33.978469020] 6448.85 Transactions per Second [20090728-10:54:33.980715907] [20090728-10:54:33.982823850] Throughput Results [20090728-10:54:33.998156974] =================== [20090728-10:54:34.001033845] Write Throughput: 25.2MB/sec [20090728-10:54:34.005085802] [20090728-10:54:34.007691538] System Call Latency statistics in millisecs [20090728-10:54:34.010052208] ===== [20090728-10:54:34.012491680] Min Avg Max Total Calls [20090728-10:54:34.015679080] ======== ======== ======== ============ [20090728-10:54:34.018201182] [ open] 0.007000 0.026075 0.154000 1528 [20090728-10:54:34.020936072] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-10:54:34.023236682] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-10:54:34.025581163] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-10:54:34.027872409] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-10:54:34.030280398] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-10:54:34.032436263] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-10:54:34.034590078] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-10:54:34.036701153] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-10:54:34.038880526] msec_range[8] 10.000000 - 20.000000 : 0 [20090728-10:54:34.041129775] msec_range[9] 5.000000 - 10.000000 : 0 [20090728-10:54:34.043247952] msec_range[10] 2.000000 - 5.000000 : 0 [20090728-10:54:34.045430978] msec_range[11] 1.000000 - 2.000000 : 0 [20090728-10:54:34.047570974] msec_range[12] 0.500000 - 1.000000 : 0 [20090728-10:54:34.049734891] msec_range[13] 0.200000 - 0.500000 : 0 [20090728-10:54:34.051826617] msec_range[14] 0.100000 - 0.200000 : 5 [20090728-10:54:34.054143147] msec_range[15] 0.050000 - 0.100000 : 172 [20090728-10:54:34.056221632] msec_range[16] 0.020000 - 0.050000 : 841 [20090728-10:54:34.058348880] msec_range[17] 0.010000 - 0.020000 : 471 [20090728-10:54:34.060420480] msec_range[18] 0.000000 - 0.010000 : 39 [20090728-10:54:34.062514621] [20090728-10:54:34.064532916] [ write] 0.495000 2.464269 154.085999 1955840 [20090728-10:54:34.066703475] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-10:54:34.068799245] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-10:54:34.070944799] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-10:54:34.073053470] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-10:54:34.075215861] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-10:54:34.078274508] msec_range[5] 100.000000 - 200.000000 : 140 [20090728-10:54:34.080538653] msec_range[6] 50.000000 - 100.000000 : 1520 [20090728-10:54:34.082909328] msec_range[7] 20.000000 - 50.000000 : 2707 [20090728-10:54:34.085305587] msec_range[8] 10.000000 - 20.000000 : 2788 [20090728-10:54:34.087809325] msec_range[9] 5.000000 - 10.000000 : 8630 [20090728-10:54:34.090212090] msec_range[10] 2.000000 - 5.000000 : 1566372 [20090728-10:54:34.092936623] msec_range[11] 1.000000 - 2.000000 : 371771 [20090728-10:54:34.095412085] msec_range[12] 0.500000 - 1.000000 : 1911 [20090728-10:54:34.097749472] msec_range[13] 0.200000 - 0.500000 : 1 [20090728-10:54:34.100105938] msec_range[14] 0.100000 - 0.200000 : 0 [20090728-10:54:34.102559398] msec_range[15] 0.050000 - 0.100000 : 0 [20090728-10:54:34.105440879] msec_range[16] 0.020000 - 0.050000 : 0 [20090728-10:54:34.108150599] msec_range[17] 0.010000 - 0.020000 : 0 [20090728-10:54:34.110701582] msec_range[18] 0.000000 - 0.010000 : 0 [20090728-10:54:34.113095665] [20090728-10:54:34.115628732] [ lseek] 0.000000 0.001790 1.908000 1955840 [20090728-10:54:34.118322531] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-10:54:34.120845738] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-10:54:34.123400369] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-10:54:34.125945321] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-10:54:34.128411082] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-10:54:34.130786484] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-10:54:34.133036280] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-10:54:34.137274203] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-10:54:34.140218751] msec_range[8] 10.000000 - 20.000000 : 0 [20090728-10:54:34.142428942] msec_range[9] 5.000000 - 10.000000 : 0 [20090728-10:54:34.145823558] msec_range[10] 2.000000 - 5.000000 : 0 [20090728-10:54:34.148344730] msec_range[11] 1.000000 - 2.000000 : 1 [20090728-10:54:34.150930934] msec_range[12] 0.500000 - 1.000000 : 8 [20090728-10:54:34.153223975] msec_range[13] 0.200000 - 0.500000 : 283 [20090728-10:54:34.155591041] msec_range[14] 0.100000 - 0.200000 : 203 [20090728-10:54:34.158068050] msec_range[15] 0.050000 - 0.100000 : 626 [20090728-10:54:34.160432271] msec_range[16] 0.020000 - 0.050000 : 2055 [20090728-10:54:34.163110609] msec_range[17] 0.010000 - 0.020000 : 1230 [20090728-10:54:34.165425532] msec_range[18] 0.000000 - 0.010000 : 1951434 [20090728-10:54:34.168093178] [20090728-10:54:34.170523640] [ close] 0.003000 0.006171 0.044000 1528 [20090728-10:54:34.172582368] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-10:54:34.174818515] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-10:54:34.177254394] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-10:54:34.179335529] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-10:54:34.181459608] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-10:54:34.183557185] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-10:54:34.185759231] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-10:54:34.187714348] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-10:54:34.189693060] msec_range[8] 10.000000 - 20.000000 : 0 [20090728-10:54:34.191908888] msec_range[9] 5.000000 - 10.000000 : 0 [20090728-10:54:34.193948930] msec_range[10] 2.000000 - 5.000000 : 0 [20090728-10:54:34.195841581] msec_range[11] 1.000000 - 2.000000 : 0 [20090728-10:54:34.197802000] msec_range[12] 0.500000 - 1.000000 : 0 [20090728-10:54:34.199777956] msec_range[13] 0.200000 - 0.500000 : 0 [20090728-10:54:34.201802312] msec_range[14] 0.100000 - 0.200000 : 0 [20090728-10:54:34.203736437] msec_range[15] 0.050000 - 0.100000 : 0 [20090728-10:54:34.205800798] msec_range[16] 0.020000 - 0.050000 : 7 [20090728-10:54:34.207942146] msec_range[17] 0.010000 - 0.020000 : 14 [20090728-10:54:34.210158883] msec_range[18] 0.000000 - 0.010000 : 1507 [20090728-10:54:34.212177786] [20090728-10:54:34.214291391] [20090728-10:54:34.216312002] [20090728-10:54:34.218313735] [20090728-10:54:34.220235735] 2.0% User Time [20090728-10:54:34.222246205] 147.3% System Time [20090728-10:54:34.224268849] 149.3% CPU Utilization [20090728-10:54:34.226498611] Profilers reporting [20090728-10:54:34.380906818] Profilers postprocessing [20090728-10:54:34.655430331] Processing File : iostat.001 [20090728-10:54:34.657861914] Discovered iostat_interval=[5] [20090728-10:54:35.427354729] Processing Directory : sar.breakout.001 [20090728-10:54:35.429569585] Discovered sar_interval=[5] [20090728-10:54:35.601113696] Processing File : mpstat.001 [20090728-10:54:35.603600950] Discovered mpstat_interval=[5] [20090728-10:54:37.095050977] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-07-28_0851/btrfsexp-7-24' [20090728-10:54:42.942800576] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090728-10:54:45.706355919] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090728-10:54:45.869510892] ONLY : Command [run random_writes_odirect__threads_0128 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb num_threads=128] found for me [20090728-10:54:45.923180432] PROCESSING COMMAND : 'run random_writes_odirect__threads_0128 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb num_threads=128' [20090728-10:54:45.972107202] new log requested [20090728-10:54:46.002647058] Running command ffsb [20090728-10:54:57.138329665] 07/28/2009-10:54:57 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb Succeeded [20090728-10:54:57.149154770] Importing argument : num_threads=128 [20090728-10:54:57.178293054] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090728-10:54:57.263045250] FFSB version 6.0-RC2.1 started [20090728-10:54:57.265147087] [20090728-10:54:57.801189934] benchmark time = 300 [20090728-10:54:57.803504160] ThreadGroup 0 [20090728-10:54:57.805637833] ================ [20090728-10:54:57.807817877] num_threads = 128 [20090728-10:54:57.809959635] [20090728-10:54:57.812272862] read_random = off [20090728-10:54:57.814522531] read_size = 0 (0B) [20090728-10:54:57.816683860] read_blocksize = 0 (0B) [20090728-10:54:57.818696393] read_skip = off [20090728-10:54:57.820800957] read_skipsize = 0 (0B) [20090728-10:54:57.822991741] [20090728-10:54:57.824869141] write_random = on [20090728-10:54:57.826832785] write_size = 5242880 (5MB) [20090728-10:54:57.828749656] fsync_file = 0 [20090728-10:54:57.830746095] write_blocksize = 4096 (4KB) [20090728-10:54:57.832834325] wait time = 0 [20090728-10:54:57.834830162] [20090728-10:54:57.836725431] op weights [20090728-10:54:57.838792634] read = 0 (0.00%) [20090728-10:54:57.840723684] readall = 0 (0.00%) [20090728-10:54:57.842863790] write = 1 (100.00%) [20090728-10:54:57.844734430] create = 0 (0.00%) [20090728-10:54:57.846740071] append = 0 (0.00%) [20090728-10:54:57.848700922] delete = 0 (0.00%) [20090728-10:54:57.850713683] metaop = 0 (0.00%) [20090728-10:54:57.852636842] createdir = 0 (0.00%) [20090728-10:54:57.854799953] stat = 0 (0.00%) [20090728-10:54:57.857373510] writeall = 0 (0.00%) [20090728-10:54:57.859538686] writeall_fsync = 0 (0.00%) [20090728-10:54:57.861440593] open_close = 0 (0.00%) [20090728-10:54:57.863654790] write_fsync = 0 (0.00%) [20090728-10:54:57.865719209] create_fsync = 0 (0.00%) [20090728-10:54:57.867730419] append_fsync = 0 (0.00%) [20090728-10:54:57.869624700] [20090728-10:54:57.871893869] FileSystem /mnt/ffsb1 [20090728-10:54:57.874152550] ========== [20090728-10:54:57.876049230] num_dirs = 0 [20090728-10:54:57.878161347] starting files = 1024 [20090728-10:54:57.880194159] [20090728-10:54:57.882122790] min file size = 104857600 (100MB) [20090728-10:54:57.884035978] max file size = 104857600 (100MB) [20090728-10:54:57.886136134] directio = on [20090728-10:54:57.888183293] alignedio = on [20090728-10:54:57.890363522] bufferedio = off [20090728-10:54:57.892191685] [20090728-10:54:57.894242037] aging is off [20090728-10:54:57.896268318] current utilization = 4.81% [20090728-10:54:57.898274253] [20090728-10:54:57.900155290] creating new fileset /mnt/ffsb1 [20090728-11:06:34.021545945] fs setup took 695 secs [20090728-11:06:35.422536581] Syncing()...1 sec [20090728-11:06:35.428528316] Starting Actual Benchmark At: Tue Jul 28 11:06:35 2009 [20090728-11:06:35.535524046] [20090728-11:11:43.516791995] Syncing()...1 sec [20090728-11:11:43.519374153] FFSB benchmark finished at: Tue Jul 28 11:11:43 2009 [20090728-11:11:43.522024349] [20090728-11:11:43.524443006] Results: [20090728-11:11:43.539774112] Benchmark took 308.09 sec [20090728-11:11:43.541931677] [20090728-11:11:43.544195287] Total Results [20090728-11:11:43.559226572] =============== [20090728-11:11:43.561653493] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090728-11:11:43.564027252] ======= ============ ========= ======= =========== ========== [20090728-11:11:43.566298906] write : 2949120 9572.14 100.000% 100.000% 37.4MB/sec [20090728-11:11:43.568345875] - [20090728-11:11:43.570431144] 9572.14 Transactions per Second [20090728-11:11:43.572557491] [20090728-11:11:43.574760266] Throughput Results [20090728-11:11:43.591282099] =================== [20090728-11:11:43.593541021] Write Throughput: 37.4MB/sec [20090728-11:11:43.595662516] [20090728-11:11:43.597893135] System Call Latency statistics in millisecs [20090728-11:11:43.600017426] ===== [20090728-11:11:43.602317191] Min Avg Max Total Calls [20090728-11:11:43.604551967] ======== ======== ======== ============ [20090728-11:11:43.606737122] [ open] 0.007000 0.027841 0.613000 2304 [20090728-11:11:43.608795155] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-11:11:43.611084136] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-11:11:43.613200149] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-11:11:43.615318176] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-11:11:43.617478642] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-11:11:43.619748494] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-11:11:43.622437533] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-11:11:43.624520919] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-11:11:43.626579639] msec_range[8] 10.000000 - 20.000000 : 0 [20090728-11:11:43.628682980] msec_range[9] 5.000000 - 10.000000 : 0 [20090728-11:11:43.630852677] msec_range[10] 2.000000 - 5.000000 : 0 [20090728-11:11:43.632733106] msec_range[11] 1.000000 - 2.000000 : 0 [20090728-11:11:43.634724355] msec_range[12] 0.500000 - 1.000000 : 1 [20090728-11:11:43.636768182] msec_range[13] 0.200000 - 0.500000 : 2 [20090728-11:11:43.639051907] msec_range[14] 0.100000 - 0.200000 : 8 [20090728-11:11:43.640940645] msec_range[15] 0.050000 - 0.100000 : 185 [20090728-11:11:43.642955066] msec_range[16] 0.020000 - 0.050000 : 1678 [20090728-11:11:43.644905057] msec_range[17] 0.010000 - 0.020000 : 394 [20090728-11:11:43.646897681] msec_range[18] 0.000000 - 0.010000 : 36 [20090728-11:11:43.648780903] [20090728-11:11:43.650719986] [ write] 0.433000 13.278659 213.503006 2949120 [20090728-11:11:43.652754285] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-11:11:43.654943546] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-11:11:43.656858948] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-11:11:43.658949498] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-11:11:43.660932853] msec_range[4] 200.000000 - 500.000000 : 65 [20090728-11:11:43.663254191] msec_range[5] 100.000000 - 200.000000 : 4542 [20090728-11:11:43.665540985] msec_range[6] 50.000000 - 100.000000 : 18501 [20090728-11:11:43.667722248] msec_range[7] 20.000000 - 50.000000 : 290251 [20090728-11:11:43.669821848] msec_range[8] 10.000000 - 20.000000 : 1637609 [20090728-11:11:43.672026521] msec_range[9] 5.000000 - 10.000000 : 773474 [20090728-11:11:43.674559100] msec_range[10] 2.000000 - 5.000000 : 198299 [20090728-11:11:43.676943385] msec_range[11] 1.000000 - 2.000000 : 23347 [20090728-11:11:43.679288731] msec_range[12] 0.500000 - 1.000000 : 3023 [20090728-11:11:43.681684327] msec_range[13] 0.200000 - 0.500000 : 9 [20090728-11:11:43.684107187] msec_range[14] 0.100000 - 0.200000 : 0 [20090728-11:11:43.686592907] msec_range[15] 0.050000 - 0.100000 : 0 [20090728-11:11:43.689168401] msec_range[16] 0.020000 - 0.050000 : 0 [20090728-11:11:43.691715216] msec_range[17] 0.010000 - 0.020000 : 0 [20090728-11:11:43.693884903] msec_range[18] 0.000000 - 0.010000 : 0 [20090728-11:11:43.696053742] [20090728-11:11:43.698215576] [ lseek] 0.000000 0.002297 10.902000 2949120 [20090728-11:11:43.700360761] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-11:11:43.703543427] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-11:11:43.706689047] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-11:11:43.709086505] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-11:11:43.712081702] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-11:11:43.715470294] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-11:11:43.717628749] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-11:11:43.719990698] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-11:11:43.722438486] msec_range[8] 10.000000 - 20.000000 : 1 [20090728-11:11:43.724893765] msec_range[9] 5.000000 - 10.000000 : 0 [20090728-11:11:43.728256991] msec_range[10] 2.000000 - 5.000000 : 0 [20090728-11:11:43.730526132] msec_range[11] 1.000000 - 2.000000 : 2 [20090728-11:11:43.732732128] msec_range[12] 0.500000 - 1.000000 : 41 [20090728-11:11:43.735157215] msec_range[13] 0.200000 - 0.500000 : 1507 [20090728-11:11:43.737571739] msec_range[14] 0.100000 - 0.200000 : 1434 [20090728-11:11:43.739803571] msec_range[15] 0.050000 - 0.100000 : 957 [20090728-11:11:43.741974983] msec_range[16] 0.020000 - 0.050000 : 3251 [20090728-11:11:43.744088890] msec_range[17] 0.010000 - 0.020000 : 4661 [20090728-11:11:43.746037032] msec_range[18] 0.000000 - 0.010000 : 2937266 [20090728-11:11:43.748020997] [20090728-11:11:43.749958573] [ close] 0.003000 0.007273 0.042000 2304 [20090728-11:11:43.751975971] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-11:11:43.753938578] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-11:11:43.755914070] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-11:11:43.757883210] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-11:11:43.759907508] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-11:11:43.761818285] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-11:11:43.763772389] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-11:11:43.765895140] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-11:11:43.768601101] msec_range[8] 10.000000 - 20.000000 : 0 [20090728-11:11:43.770608055] msec_range[9] 5.000000 - 10.000000 : 0 [20090728-11:11:43.772634157] msec_range[10] 2.000000 - 5.000000 : 0 [20090728-11:11:43.774722457] msec_range[11] 1.000000 - 2.000000 : 0 [20090728-11:11:43.776777601] msec_range[12] 0.500000 - 1.000000 : 0 [20090728-11:11:43.778668473] msec_range[13] 0.200000 - 0.500000 : 0 [20090728-11:11:43.780641021] msec_range[14] 0.100000 - 0.200000 : 0 [20090728-11:11:43.782561154] msec_range[15] 0.050000 - 0.100000 : 0 [20090728-11:11:43.784526486] msec_range[16] 0.020000 - 0.050000 : 7 [20090728-11:11:43.786425374] msec_range[17] 0.010000 - 0.020000 : 101 [20090728-11:11:43.788360123] msec_range[18] 0.000000 - 0.010000 : 2196 [20090728-11:11:43.790579627] [20090728-11:11:43.792686769] [20090728-11:11:43.794849891] [20090728-11:11:43.797051928] [20090728-11:11:43.799189895] 3.5% User Time [20090728-11:11:43.801320712] 322.9% System Time [20090728-11:11:43.803250578] 326.4% CPU Utilization [20090728-11:11:43.805241330] Profilers reporting [20090728-11:11:43.965246600] Profilers postprocessing [20090728-11:11:44.229914449] Processing File : iostat.001 [20090728-11:11:44.232101463] Discovered iostat_interval=[5] [20090728-11:11:45.009514452] Processing Directory : sar.breakout.001 [20090728-11:11:45.011793056] Discovered sar_interval=[5] [20090728-11:11:45.184776917] Processing File : mpstat.001 [20090728-11:11:45.187131288] Discovered mpstat_interval=[5] [20090728-11:11:46.627325057] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-07-28_0851/btrfsexp-7-24' [20090728-11:11:51.529306651] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20090728-11:11:54.709810468] PROCESSING COMMAND : 'mkfs.btrfs /dev/ffsbdev1' [20090728-11:11:54.759859252] [20090728-11:11:54.762196364] WARNING! - Btrfs v0.18-13-gb8420fa IS EXPERIMENTAL [20090728-11:11:54.764405559] WARNING! - see http://btrfs.wiki.kernel.org before using [20090728-11:11:54.766691690] [20090728-11:11:54.768964428] fs created label (null) on /dev/ffsbdev1 [20090728-11:11:54.771277690] nodesize 4096 leafsize 4096 sectorsize 4096 size 2.18TB [20090728-11:11:54.773274576] Btrfs v0.18-13-gb8420fa [20090728-11:11:54.867358206] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20090728-11:11:54.952610648] ONLY : Command [run large_file_creates__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/large_file_creates.ffsb num_threads=1] found for me [20090728-11:11:55.006525074] PROCESSING COMMAND : 'run large_file_creates__threads_0001 ffsb http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/large_file_creates.ffsb num_threads=1' [20090728-11:11:55.055783045] new log requested [20090728-11:11:55.086812463] Running command ffsb [20090728-11:12:06.349264784] 07/28/2009-11:12:06 Getting file: http://hks.austin.ibm.com/users/corry/btrfs/ffsb/profiles/btrfs1/large_file_creates.ffsb Succeeded [20090728-11:12:06.360885044] Importing argument : num_threads=1 [20090728-11:12:06.388818339] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20090728-11:12:06.472538669] FFSB version 6.0-RC2.1 started [20090728-11:12:06.474904979] [20090728-11:12:06.477042688] benchmark time = 300 [20090728-11:12:06.479250957] ThreadGroup 0 [20090728-11:12:06.481388740] ================ [20090728-11:12:06.483488106] num_threads = 1 [20090728-11:12:06.485779880] [20090728-11:12:06.488103124] read_random = off [20090728-11:12:06.490378854] read_size = 0 (0B) [20090728-11:12:06.492576244] read_blocksize = 0 (0B) [20090728-11:12:06.494688528] read_skip = off [20090728-11:12:06.496724591] read_skipsize = 0 (0B) [20090728-11:12:06.498682982] [20090728-11:12:06.500758227] write_random = off [20090728-11:12:06.502779806] write_size = 0 (0B) [20090728-11:12:06.504754180] fsync_file = 0 [20090728-11:12:06.506626860] write_blocksize = 4096 (4KB) [20090728-11:12:06.508599336] wait time = 0 [20090728-11:12:06.510509576] [20090728-11:12:06.512443974] op weights [20090728-11:12:06.514326630] read = 0 (0.00%) [20090728-11:12:06.516312445] readall = 0 (0.00%) [20090728-11:12:06.518218265] write = 0 (0.00%) [20090728-11:12:06.520161035] create = 1 (100.00%) [20090728-11:12:06.522034872] append = 0 (0.00%) [20090728-11:12:06.524000055] delete = 0 (0.00%) [20090728-11:12:06.525895182] metaop = 0 (0.00%) [20090728-11:12:06.527844162] createdir = 0 (0.00%) [20090728-11:12:06.529703003] stat = 0 (0.00%) [20090728-11:12:06.531698482] writeall = 0 (0.00%) [20090728-11:12:06.533570899] writeall_fsync = 0 (0.00%) [20090728-11:12:06.535439124] open_close = 0 (0.00%) [20090728-11:12:06.537342747] write_fsync = 0 (0.00%) [20090728-11:12:06.539299890] create_fsync = 0 (0.00%) [20090728-11:12:06.541203622] append_fsync = 0 (0.00%) [20090728-11:12:06.543161596] [20090728-11:12:06.545028920] FileSystem /mnt/ffsb1 [20090728-11:12:06.546991012] ========== [20090728-11:12:06.548882055] num_dirs = 0 [20090728-11:12:06.550810902] starting files = 0 [20090728-11:12:06.552711100] [20090728-11:12:06.554676976] min file size = 1073741824 (1GB) [20090728-11:12:06.556543823] max file size = 1073741824 (1GB) [20090728-11:12:06.558422707] directio = off [20090728-11:12:06.560329837] alignedio = on [20090728-11:12:06.562279408] bufferedio = off [20090728-11:12:06.564159220] [20090728-11:12:06.566094682] aging is off [20090728-11:12:06.567952569] current utilization = 0.00% [20090728-11:12:06.569942485] [20090728-11:12:06.571820636] creating new fileset /mnt/ffsb1 [20090728-11:12:06.573774209] fs setup took 0 secs [20090728-11:12:06.965335801] Syncing()...0 sec [20090728-11:12:06.967594642] Starting Actual Benchmark At: Tue Jul 28 11:12:06 2009 [20090728-11:12:06.983041287] [20090728-11:17:10.156315489] Syncing()...2 sec [20090728-11:17:10.209494988] FFSB benchmark finished at: Tue Jul 28 11:17:09 2009 [20090728-11:17:10.212004845] [20090728-11:17:10.213936554] Results: [20090728-11:17:10.258862330] Benchmark took 302.88 sec [20090728-11:17:10.261335015] [20090728-11:17:10.263687876] Total Results [20090728-11:17:10.278849657] =============== [20090728-11:17:10.281108384] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20090728-11:17:10.283483588] ======= ============ ========= ======= =========== ========== [20090728-11:17:10.285851173] create : 17039360 56257.37 100.000% 100.000% 220MB/sec [20090728-11:17:10.288405993] - [20090728-11:17:10.290837540] 56257.37 Transactions per Second [20090728-11:17:10.293300789] [20090728-11:17:10.295507350] Throughput Results [20090728-11:17:10.310269952] =================== [20090728-11:17:10.312236519] Write Throughput: 220MB/sec [20090728-11:17:10.315161085] [20090728-11:17:10.317193989] System Call Latency statistics in millisecs [20090728-11:17:10.319223575] ===== [20090728-11:17:10.321253335] Min Avg Max Total Calls [20090728-11:17:10.323238355] ======== ======== ======== ============ [20090728-11:17:10.325278220] [ open] 0.074000 0.285831 5.544000 65 [20090728-11:17:10.327221389] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-11:17:10.329181866] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-11:17:10.331088734] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-11:17:10.333076419] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-11:17:10.334985167] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-11:17:10.336956153] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-11:17:10.338857329] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-11:17:10.340840515] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-11:17:10.342760389] msec_range[8] 10.000000 - 20.000000 : 0 [20090728-11:17:10.344732437] msec_range[9] 5.000000 - 10.000000 : 1 [20090728-11:17:10.346792967] msec_range[10] 2.000000 - 5.000000 : 0 [20090728-11:17:10.348703261] msec_range[11] 1.000000 - 2.000000 : 2 [20090728-11:17:10.350684242] msec_range[12] 0.500000 - 1.000000 : 6 [20090728-11:17:10.352621034] msec_range[13] 0.200000 - 0.500000 : 1 [20090728-11:17:10.354697811] msec_range[14] 0.100000 - 0.200000 : 29 [20090728-11:17:10.357688368] msec_range[15] 0.050000 - 0.100000 : 26 [20090728-11:17:10.360021927] msec_range[16] 0.020000 - 0.050000 : 0 [20090728-11:17:10.362216749] msec_range[17] 0.010000 - 0.020000 : 0 [20090728-11:17:10.364630146] msec_range[18] 0.000000 - 0.010000 : 0 [20090728-11:17:10.366864694] [20090728-11:17:10.369049924] [ write] 0.008000 0.017255 864.692017 17039360 [20090728-11:17:10.370999807] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-11:17:10.373039393] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-11:17:10.375056080] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-11:17:10.377401066] msec_range[3] 500.000000 - 1000.000000 : 2 [20090728-11:17:10.379873425] msec_range[4] 200.000000 - 500.000000 : 2 [20090728-11:17:10.382110063] msec_range[5] 100.000000 - 200.000000 : 2 [20090728-11:17:10.384279081] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-11:17:10.386388026] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-11:17:10.388567809] msec_range[8] 10.000000 - 20.000000 : 0 [20090728-11:17:10.390490303] msec_range[9] 5.000000 - 10.000000 : 0 [20090728-11:17:10.392438595] msec_range[10] 2.000000 - 5.000000 : 39 [20090728-11:17:10.394568345] msec_range[11] 1.000000 - 2.000000 : 60 [20090728-11:17:10.396627703] msec_range[12] 0.500000 - 1.000000 : 19 [20090728-11:17:10.398592031] msec_range[13] 0.200000 - 0.500000 : 131 [20090728-11:17:10.400627379] msec_range[14] 0.100000 - 0.200000 : 277 [20090728-11:17:10.402549562] msec_range[15] 0.050000 - 0.100000 : 48257 [20090728-11:17:10.404554483] msec_range[16] 0.020000 - 0.050000 : 5910848 [20090728-11:17:10.406555049] msec_range[17] 0.010000 - 0.020000 : 11079658 [20090728-11:17:10.408611590] msec_range[18] 0.000000 - 0.010000 : 65 [20090728-11:17:10.410706898] [20090728-11:17:10.412892010] [ close] 0.007000 0.008369 0.018000 65 [20090728-11:17:10.414862853] msec_range[0] 5000.000000 - 10000.000000 : 0 [20090728-11:17:10.417012303] msec_range[1] 2000.000000 - 5000.000000 : 0 [20090728-11:17:10.419097779] msec_range[2] 1000.000000 - 2000.000000 : 0 [20090728-11:17:10.421183674] msec_range[3] 500.000000 - 1000.000000 : 0 [20090728-11:17:10.423125140] msec_range[4] 200.000000 - 500.000000 : 0 [20090728-11:17:10.425174433] msec_range[5] 100.000000 - 200.000000 : 0 [20090728-11:17:10.427095571] msec_range[6] 50.000000 - 100.000000 : 0 [20090728-11:17:10.429099951] msec_range[7] 20.000000 - 50.000000 : 0 [20090728-11:17:10.430999037] msec_range[8] 10.000000 - 20.000000 : 0 [20090728-11:17:10.432966358] msec_range[9] 5.000000 - 10.000000 : 0 [20090728-11:17:10.434869044] msec_range[10] 2.000000 - 5.000000 : 0 [20090728-11:17:10.436852808] msec_range[11] 1.000000 - 2.000000 : 0 [20090728-11:17:10.438749440] msec_range[12] 0.500000 - 1.000000 : 0 [20090728-11:17:10.440734428] msec_range[13] 0.200000 - 0.500000 : 0 [20090728-11:17:10.442625004] msec_range[14] 0.100000 - 0.200000 : 0 [20090728-11:17:10.444612249] msec_range[15] 0.050000 - 0.100000 : 0 [20090728-11:17:10.446766735] msec_range[16] 0.020000 - 0.050000 : 0 [20090728-11:17:10.449037267] msec_range[17] 0.010000 - 0.020000 : 5 [20090728-11:17:10.451268248] msec_range[18] 0.000000 - 0.010000 : 60 [20090728-11:17:10.453385930] [20090728-11:17:10.455470109] [20090728-11:17:10.457393364] [20090728-11:17:10.459534488] [20090728-11:17:10.461644567] 3.3% User Time [20090728-11:17:10.463721773] 95.3% System Time [20090728-11:17:10.465653527] 98.6% CPU Utilization [20090728-11:17:10.467684902] Profilers reporting [20090728-11:17:10.830277469] Profilers postprocessing [20090728-11:17:11.118827392] Processing File : iostat.001 [20090728-11:17:11.121094432] Discovered iostat_interval=[5] [20090728-11:17:11.905335099] Processing Directory : sar.breakout.001 [20090728-11:17:11.907760531] Discovered sar_interval=[5] [20090728-11:17:12.081120135] Processing File : mpstat.001 [20090728-11:17:12.083498601] Discovered mpstat_interval=[5] [20090728-11:17:13.635673868] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2009-07-28_0851/btrfsexp-7-24'