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