[20081217-08:01:41.511957360] PROCESSING COMMAND : 'clearprofilers' [20081217-08:01:41.766734630] PROCESSING COMMAND : 'useprofiler iostat 5' [20081217-08:01:41.873321226] Checking for sar... [20081217-08:01:41.875564605] found [20081217-08:01:42.011485712] PROCESSING COMMAND : 'useprofiler sar 5' [20081217-08:01:42.118456250] Checking for sar... [20081217-08:01:42.120571966] found [20081217-08:01:42.257276394] PROCESSING COMMAND : 'useprofiler mpstat 5' [20081217-08:01:42.362923778] Checking for sar... [20081217-08:01:42.365304301] found [20081217-08:01:42.533471129] PROCESSING COMMAND : 'useprofiler oprofile' [20081217-08:01:42.749274959] Checking for binutils-2.18 ... Already installed. [20081217-08:01:42.753462779] mv: cannot stat `lib64/*': No such file or directory [20081217-08:01:42.762196623] rmdir: lib64: No such file or directory [20081217-08:01:42.833385853] Checking for gettext-0.17 ... Already installed. [20081217-08:01:42.879422871] popt32-1.10.4 already installed. [20081217-08:01:42.894479772] popt64-1.10.4 already installed. [20081217-08:01:42.924482209] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-08:01:42.976800679] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-08:01:43.055475784] Daemon not running [20081217-08:01:43.078009712] Unloading oprofile module [20081217-08:01:43.282505297] Daemon not running [20081217-08:01:45.574162684] OPROFILE : using callgraph [5] [20081217-08:01:45.804743947] Daemon not running [20081217-08:01:45.806721045] Separate options: none [20081217-08:01:45.808938567] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-08:01:45.811073750] Image filter: none [20081217-08:01:45.813124733] Call-graph depth: 5 [20081217-08:01:46.017308555] PROCESSING COMMAND : 'umount /mnt/ffsb1 > /dev/null 2>&1' [20081217-08:01:46.093485018] PROCESSING COMMAND : 'set-sched noop' [20081217-08:01:46.492504179] PROCESSING COMMAND : 'mkresultdirs hks.austin.ibm.com benchmarks/results/btrfs/ffsb btrfs1 2008-12-17_0801 btrfs-baseline' [20081217-08:01:46.838706753] Connecting to hks.austin.ibm.com... [20081217-08:01:46.840919471] Remote working directory: /opt [20081217-08:01:46.842867897] Remote working directory: /opt/benchmarks/results/btrfs/ffsb [20081217-08:01:46.844619191] Couldn't create directory: Failure [20081217-08:01:46.846555105] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1 [20081217-08:01:46.848727838] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs1 [20081217-08:01:46.850977393] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0801 [20081217-08:01:46.853061671] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0801 [20081217-08:01:46.855153496] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0801/btrfs-baseline [20081217-08:01:46.926897866] PROCESSING COMMAND : 'mkfs.btrfs -V 2>&1' [20081217-08:01:46.958007616] mkfs.btrfs: invalid option -- V [20081217-08:01:46.960339099] usage: mkfs.btrfs [options] dev [ dev ... ] [20081217-08:01:46.962407036] options: [20081217-08:01:46.964368628] -b --byte-count total number of bytes in the FS [20081217-08:01:46.966259312] -l --leafsize size of btree leaves [20081217-08:01:46.968318413] -n --nodesize size of btree leaves [20081217-08:01:46.970540906] -s --sectorsize min block allocation [20081217-08:01:46.972466799] Btrfs v0.16-28-gb238b4b [20081217-08:01:47.054961312] PROCESSING COMMAND : 'mkfs.btrfs /dev/ffsbdev1' [20081217-08:01:47.094935716] fs created label (null) on /dev/ffsbdev1 [20081217-08:01:47.099403094] nodesize 4096 leafsize 4096 sectorsize 4096 size 2.18TB [20081217-08:01:47.101323843] Btrfs v0.16-28-gb238b4b [20081217-08:01:47.270109345] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-08:01:47.376731754] PROCESSING COMMAND : 'run sequential_reads__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb num_threads=1' [20081217-08:01:47.497165144] new log requested [20081217-08:01:47.521604902] Running command ffsb [20081217-08:01:57.277946288] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb [20081217-08:01:57.295994938] Importing argument : num_threads=1 [20081217-08:01:57.322716343] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-08:01:57.412344728] Checking for sar... [20081217-08:01:57.414634951] found [20081217-08:01:57.471960073] Checking for sar... [20081217-08:01:57.474192776] found [20081217-08:01:57.529927797] Checking for sar... [20081217-08:01:57.532150619] found [20081217-08:01:57.661278450] Checking for binutils-2.18 ... Already installed. [20081217-08:01:57.665882307] mv: cannot stat `lib64/*': No such file or directory [20081217-08:01:57.668651982] rmdir: lib64: No such file or directory [20081217-08:01:57.728698688] Checking for gettext-0.17 ... Already installed. [20081217-08:01:57.769869719] popt32-1.10.4 already installed. [20081217-08:01:57.785090678] popt64-1.10.4 already installed. [20081217-08:01:57.815929899] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-08:01:57.870043401] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-08:01:57.949016460] Daemon not running [20081217-08:01:57.959712218] Unloading oprofile module [20081217-08:01:58.078431448] Daemon not running [20081217-08:01:58.306394582] OPROFILE : using callgraph [5] [20081217-08:01:58.538981081] Daemon not running [20081217-08:01:58.541222626] Separate options: none [20081217-08:01:58.543384496] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-08:01:58.545390509] Image filter: none [20081217-08:01:58.547542930] Call-graph depth: 5 [20081217-08:01:58.629116663] FFSB version 6.0-RC2 started [20081217-08:01:58.631355703] [20081217-08:01:58.633552416] benchmark time = 300 [20081217-08:01:58.635548669] ThreadGroup 0 [20081217-08:01:58.637737451] ================ [20081217-08:01:58.639851773] num_threads = 1 [20081217-08:01:58.641831374] [20081217-08:01:58.643893346] read_random = off [20081217-08:01:58.645788065] read_size = 0 (0B) [20081217-08:01:58.647669091] read_blocksize = 4096 (4KB) [20081217-08:01:58.649532521] read_skip = off [20081217-08:01:58.651332093] read_skipsize = 0 (0B) [20081217-08:01:58.653320548] [20081217-08:01:58.655166858] write_random = off [20081217-08:01:58.656982758] write_size = 0 (0B) [20081217-08:01:58.658795625] fsync_file = 0 [20081217-08:01:58.660700866] write_blocksize = 0 (0B) [20081217-08:01:58.662591178] wait time = 0 [20081217-08:01:58.664370937] [20081217-08:01:58.666244409] op weights [20081217-08:01:58.668066754] read = 0 (0.00%) [20081217-08:01:58.669925930] readall = 1 (100.00%) [20081217-08:01:58.671704499] write = 0 (0.00%) [20081217-08:01:58.673581154] create = 0 (0.00%) [20081217-08:01:58.675458125] append = 0 (0.00%) [20081217-08:01:58.677234037] delete = 0 (0.00%) [20081217-08:01:58.679121493] metaop = 0 (0.00%) [20081217-08:01:58.680931872] createdir = 0 (0.00%) [20081217-08:01:58.682792706] stat = 0 (0.00%) [20081217-08:01:58.684568079] writeall = 0 (0.00%) [20081217-08:01:58.686460022] writeall_fsync = 0 (0.00%) [20081217-08:01:58.688405707] open_close = 0 (0.00%) [20081217-08:01:58.690184164] write_fsync = 0 (0.00%) [20081217-08:01:58.692080870] create_fsync = 0 (0.00%) [20081217-08:01:58.693949911] append_fsync = 0 (0.00%) [20081217-08:01:58.695731604] [20081217-08:01:58.697607794] FileSystem /mnt/ffsb1 [20081217-08:01:58.699434924] ========== [20081217-08:01:58.701181005] num_dirs = 0 [20081217-08:01:58.703106850] starting files = 1024 [20081217-08:01:58.704916324] [20081217-08:01:58.706809823] min file size = 104857600 (100MB) [20081217-08:01:58.708604846] max file size = 104857600 (100MB) [20081217-08:01:58.710504609] directio = off [20081217-08:01:58.712403444] alignedio = on [20081217-08:01:58.714224635] bufferedio = off [20081217-08:01:58.716132099] [20081217-08:01:58.717909925] aging is off [20081217-08:01:58.719796166] current utilization = 0.00% [20081217-08:01:58.721591317] [20081217-08:01:58.723512937] checking existing fs: /mnt/ffsb1 [20081217-08:01:58.725410857] opendir: No such file or directory [20081217-08:01:58.727187279] recreating new fileset [20081217-08:16:37.174645641] fs setup took 878 secs [20081217-08:16:38.502597277] Syncing()...1 sec [20081217-08:16:38.505097781] Starting Actual Benchmark At: Wed Dec 17 08:16:38 2008 [20081217-08:16:38.547933754] [20081217-08:21:40.893270505] Syncing()...0 sec [20081217-08:21:40.928784726] FFSB benchmark finished at: Wed Dec 17 08:21:40 2008 [20081217-08:21:40.931758064] [20081217-08:21:40.934492587] Results: [20081217-08:21:40.990658351] Benchmark took 302.07 sec [20081217-08:21:40.993348230] [20081217-08:21:40.995912085] Total Results [20081217-08:21:41.010928879] =============== [20081217-08:21:41.013107607] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-08:21:41.015600205] ======= ============ ========= ======= =========== ========== [20081217-08:21:41.017773747] readall : 19481600 64494.59 100.000% 100.000% 252MB/sec [20081217-08:21:41.019807597] - [20081217-08:21:41.022174721] 64494.59 Transactions per Second [20081217-08:21:41.024468565] [20081217-08:21:41.026882688] Throughput Results [20081217-08:21:41.042478213] =================== [20081217-08:21:41.044695203] Read Throughput: 252MB/sec [20081217-08:21:41.047093085] [20081217-08:21:41.049522039] System Call Latency statistics in millisecs [20081217-08:21:41.051878993] ===== [20081217-08:21:41.054176401] Min Avg Max Total Calls [20081217-08:21:41.056845872] ======== ======== ======== ============ [20081217-08:21:41.059193004] [ open] 0.017000 0.312724 6.359000 761 [20081217-08:21:41.061254182] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-08:21:41.063277124] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-08:21:41.065553434] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-08:21:41.067680973] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-08:21:41.069681793] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-08:21:41.071648193] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-08:21:41.073864182] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-08:21:41.075976127] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-08:21:41.077951259] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-08:21:41.080026140] msec_range[9] 5.000000 - 10.000000 : 9 [20081217-08:21:41.082255617] msec_range[10] 2.000000 - 5.000000 : 38 [20081217-08:21:41.084397122] msec_range[11] 1.000000 - 2.000000 : 4 [20081217-08:21:41.086468076] msec_range[12] 0.500000 - 1.000000 : 19 [20081217-08:21:41.088455642] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-08:21:41.090671241] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-08:21:41.092790849] msec_range[15] 0.050000 - 0.100000 : 169 [20081217-08:21:41.094791073] msec_range[16] 0.020000 - 0.050000 : 520 [20081217-08:21:41.096819558] msec_range[17] 0.010000 - 0.020000 : 2 [20081217-08:21:41.099263353] msec_range[18] 0.000000 - 0.010000 : 0 [20081217-08:21:41.101588532] [20081217-08:21:41.103845288] [ read] 0.001000 0.015096 60.592999 19481600 [20081217-08:21:41.105993425] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-08:21:41.108200040] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-08:21:41.110356219] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-08:21:41.112700048] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-08:21:41.114993674] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-08:21:41.117218855] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-08:21:41.194918573] msec_range[6] 50.000000 - 100.000000 : 2 [20081217-08:21:41.197103010] msec_range[7] 20.000000 - 50.000000 : 199 [20081217-08:21:41.199228585] msec_range[8] 10.000000 - 20.000000 : 2143 [20081217-08:21:41.201431300] msec_range[9] 5.000000 - 10.000000 : 17414 [20081217-08:21:41.203498129] msec_range[10] 2.000000 - 5.000000 : 4223 [20081217-08:21:41.205667371] msec_range[11] 1.000000 - 2.000000 : 2124 [20081217-08:21:41.207816592] msec_range[12] 0.500000 - 1.000000 : 3215 [20081217-08:21:41.210245806] msec_range[13] 0.200000 - 0.500000 : 1625 [20081217-08:21:41.212630396] msec_range[14] 0.100000 - 0.200000 : 7610 [20081217-08:21:41.214813166] msec_range[15] 0.050000 - 0.100000 : 17261 [20081217-08:21:41.217033319] msec_range[16] 0.020000 - 0.050000 : 65819 [20081217-08:21:41.220164898] msec_range[17] 0.010000 - 0.020000 : 700406 [20081217-08:21:41.223287623] msec_range[18] 0.000000 - 0.010000 : 18659559 [20081217-08:21:41.225673862] [20081217-08:21:41.228059488] [ close] 0.003000 0.007229 0.020000 761 [20081217-08:21:41.230528453] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-08:21:41.232972741] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-08:21:41.235623040] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-08:21:41.238129504] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-08:21:41.240533303] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-08:21:41.243176124] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-08:21:41.245673616] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-08:21:41.248078167] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-08:21:41.250178258] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-08:21:41.252410082] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-08:21:41.254656946] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-08:21:41.256681988] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-08:21:41.259353274] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-08:21:41.261582038] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-08:21:41.263783677] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-08:21:41.265996413] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-08:21:41.268484103] msec_range[16] 0.020000 - 0.050000 : 1 [20081217-08:21:41.270808364] msec_range[17] 0.010000 - 0.020000 : 88 [20081217-08:21:41.272877342] msec_range[18] 0.000000 - 0.010000 : 672 [20081217-08:21:41.274873254] [20081217-08:21:41.277104835] [20081217-08:21:41.279363463] [20081217-08:21:41.281377879] [20081217-08:21:41.283371733] 4.3% User Time [20081217-08:21:41.286156199] 77.6% System Time [20081217-08:21:41.288710923] 81.9% CPU Utilization [20081217-08:21:41.291086174] Profilers reporting [20081217-08:22:08.475717652] Profilers postprocessing [20081217-08:22:09.614549676] Stopping profiling. [20081217-08:22:09.619014072] Killing daemon. [20081217-08:22:12.015362700] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0001.08-12-17_08.01.47/analysis/oprofile.001 [20081217-08:22:12.017669546] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0001.08-12-17_08.01.47/analysis/oprofile-brief.001 [20081217-08:22:12.234640137] Processing File : mpstat.001 [20081217-08:22:12.236852301] Discovered mpstat_interval=[5] [20081217-08:22:13.172054265] Processing Directory : sar.breakout.001 [20081217-08:22:13.174392855] Discovered sar_interval=[5] [20081217-08:22:13.395226973] Processing File : iostat.001 [20081217-08:22:13.397424724] Discovered iostat_interval=[5] [20081217-08:22:16.325534822] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0801/btrfs-baseline' [20081217-08:22:27.931751711] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-08:22:30.753157637] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-08:22:30.890814439] PROCESSING COMMAND : 'run sequential_reads__threads_0016 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb num_threads=16' [20081217-08:22:30.935731877] new log requested [20081217-08:22:30.960106242] Running command ffsb [20081217-08:22:40.695187447] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb [20081217-08:22:40.716777060] Importing argument : num_threads=16 [20081217-08:22:40.743021103] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-08:22:40.842915930] Checking for sar... [20081217-08:22:40.845055819] found [20081217-08:22:40.901811880] Checking for sar... [20081217-08:22:40.904061276] found [20081217-08:22:40.959876034] Checking for sar... [20081217-08:22:40.961959703] found [20081217-08:22:41.116337421] Checking for binutils-2.18 ... Already installed. [20081217-08:22:41.120865443] mv: cannot stat `lib64/*': No such file or directory [20081217-08:22:41.133587046] rmdir: lib64: No such file or directory [20081217-08:22:41.204796518] Checking for gettext-0.17 ... Already installed. [20081217-08:22:41.251520317] popt32-1.10.4 already installed. [20081217-08:22:41.266724756] popt64-1.10.4 already installed. [20081217-08:22:41.297755022] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-08:22:41.349915068] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-08:22:41.430206470] Daemon not running [20081217-08:22:41.449296178] Unloading oprofile module [20081217-08:22:41.680082687] Daemon not running [20081217-08:22:42.846860012] OPROFILE : using callgraph [5] [20081217-08:22:43.078687689] Daemon not running [20081217-08:22:43.080660952] Separate options: none [20081217-08:22:43.082866401] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-08:22:43.084896981] Image filter: none [20081217-08:22:43.086761486] Call-graph depth: 5 [20081217-08:22:43.167704519] FFSB version 6.0-RC2 started [20081217-08:22:43.169823209] [20081217-08:22:43.225773243] benchmark time = 300 [20081217-08:22:43.227731171] ThreadGroup 0 [20081217-08:22:43.229490738] ================ [20081217-08:22:43.231480440] num_threads = 16 [20081217-08:22:43.233692333] [20081217-08:22:43.235656698] read_random = off [20081217-08:22:43.237388185] read_size = 0 (0B) [20081217-08:22:43.239253861] read_blocksize = 4096 (4KB) [20081217-08:22:43.241267650] read_skip = off [20081217-08:22:43.243473408] read_skipsize = 0 (0B) [20081217-08:22:43.245320768] [20081217-08:22:43.247280910] write_random = off [20081217-08:22:43.249152360] write_size = 0 (0B) [20081217-08:22:43.250997193] fsync_file = 0 [20081217-08:22:43.252776328] write_blocksize = 0 (0B) [20081217-08:22:43.254614543] wait time = 0 [20081217-08:22:43.256407774] [20081217-08:22:43.258251380] op weights [20081217-08:22:43.260002636] read = 0 (0.00%) [20081217-08:22:43.261841756] readall = 1 (100.00%) [20081217-08:22:43.263630588] write = 0 (0.00%) [20081217-08:22:43.265435680] create = 0 (0.00%) [20081217-08:22:43.267164445] append = 0 (0.00%) [20081217-08:22:43.268983625] delete = 0 (0.00%) [20081217-08:22:43.270729759] metaop = 0 (0.00%) [20081217-08:22:43.272507142] createdir = 0 (0.00%) [20081217-08:22:43.274242140] stat = 0 (0.00%) [20081217-08:22:43.276050074] writeall = 0 (0.00%) [20081217-08:22:43.277776185] writeall_fsync = 0 (0.00%) [20081217-08:22:43.279574505] open_close = 0 (0.00%) [20081217-08:22:43.281296716] write_fsync = 0 (0.00%) [20081217-08:22:43.283106739] create_fsync = 0 (0.00%) [20081217-08:22:43.284886289] append_fsync = 0 (0.00%) [20081217-08:22:43.286699629] [20081217-08:22:43.288402158] FileSystem /mnt/ffsb1 [20081217-08:22:43.290213560] ========== [20081217-08:22:43.291999648] num_dirs = 0 [20081217-08:22:43.293797639] starting files = 1024 [20081217-08:22:43.295508787] [20081217-08:22:43.297303490] min file size = 104857600 (100MB) [20081217-08:22:43.299053596] max file size = 104857600 (100MB) [20081217-08:22:43.300872956] directio = off [20081217-08:22:43.302616729] alignedio = on [20081217-08:22:43.304442741] bufferedio = off [20081217-08:22:43.306302736] [20081217-08:22:43.308127603] aging is off [20081217-08:22:43.310105577] current utilization = 4.47% [20081217-08:22:43.312053387] [20081217-08:22:43.313897048] checking existing fs: /mnt/ffsb1 [20081217-08:22:43.530608572] fs setup took 0 secs [20081217-08:22:44.378291633] Syncing()...0 sec [20081217-08:22:44.380449537] Starting Actual Benchmark At: Wed Dec 17 08:22:44 2008 [20081217-08:22:44.393316248] [20081217-08:27:48.939493136] Syncing()...1 sec [20081217-08:27:49.017238618] FFSB benchmark finished at: Wed Dec 17 08:27:48 2008 [20081217-08:27:49.020133423] [20081217-08:27:49.022840005] Results: [20081217-08:27:49.078582101] Benchmark took 304.19 sec [20081217-08:27:49.081336422] [20081217-08:27:49.083944996] Total Results [20081217-08:27:49.099109747] =============== [20081217-08:27:49.101291356] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-08:27:49.103835771] ======= ============ ========= ======= =========== ========== [20081217-08:27:49.106205977] readall : 38425600 126321.60 100.000% 100.000% 493MB/sec [20081217-08:27:49.108459592] - [20081217-08:27:49.111169764] 126321.60 Transactions per Second [20081217-08:27:49.113546801] [20081217-08:27:49.115897166] Throughput Results [20081217-08:27:49.131294266] =================== [20081217-08:27:49.134300769] Read Throughput: 493MB/sec [20081217-08:27:49.136770680] [20081217-08:27:49.139143025] System Call Latency statistics in millisecs [20081217-08:27:49.141489522] ===== [20081217-08:27:49.143917454] Min Avg Max Total Calls [20081217-08:27:49.146511211] ======== ======== ======== ============ [20081217-08:27:49.148893585] [ open] 0.008000 1.068967 49.576000 1501 [20081217-08:27:49.151296021] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-08:27:49.153521902] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-08:27:49.155782443] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-08:27:49.157950681] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-08:27:49.160274088] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-08:27:49.162410451] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-08:27:49.164638892] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-08:27:49.166751118] msec_range[7] 20.000000 - 50.000000 : 8 [20081217-08:27:49.168975106] msec_range[8] 10.000000 - 20.000000 : 50 [20081217-08:27:49.171095383] msec_range[9] 5.000000 - 10.000000 : 61 [20081217-08:27:49.173319204] msec_range[10] 2.000000 - 5.000000 : 35 [20081217-08:27:49.175436114] msec_range[11] 1.000000 - 2.000000 : 1 [20081217-08:27:49.177671140] msec_range[12] 0.500000 - 1.000000 : 4 [20081217-08:27:49.179786767] msec_range[13] 0.200000 - 0.500000 : 3 [20081217-08:27:49.181970153] msec_range[14] 0.100000 - 0.200000 : 102 [20081217-08:27:49.184114589] msec_range[15] 0.050000 - 0.100000 : 665 [20081217-08:27:49.186311756] msec_range[16] 0.020000 - 0.050000 : 545 [20081217-08:27:49.188428911] msec_range[17] 0.010000 - 0.020000 : 25 [20081217-08:27:49.190718271] msec_range[18] 0.000000 - 0.010000 : 2 [20081217-08:27:49.192913368] [20081217-08:27:49.195142257] [ read] 0.001000 0.125353 10778.860352 38425600 [20081217-08:27:49.197257413] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-08:27:49.199604246] msec_range[1] 2000.000000 - 5000.000000 : 2 [20081217-08:27:49.201978363] msec_range[2] 1000.000000 - 2000.000000 : 13 [20081217-08:27:49.247456729] msec_range[3] 500.000000 - 1000.000000 : 17 [20081217-08:27:49.250085794] msec_range[4] 200.000000 - 500.000000 : 2108 [20081217-08:27:49.252527068] msec_range[5] 100.000000 - 200.000000 : 13696 [20081217-08:27:49.255056080] msec_range[6] 50.000000 - 100.000000 : 13772 [20081217-08:27:49.257447566] msec_range[7] 20.000000 - 50.000000 : 17925 [20081217-08:27:49.259766125] msec_range[8] 10.000000 - 20.000000 : 17491 [20081217-08:27:49.262407060] msec_range[9] 5.000000 - 10.000000 : 22175 [20081217-08:27:49.264909842] msec_range[10] 2.000000 - 5.000000 : 13692 [20081217-08:27:49.267327105] msec_range[11] 1.000000 - 2.000000 : 4421 [20081217-08:27:49.269460370] msec_range[12] 0.500000 - 1.000000 : 3099 [20081217-08:27:49.271645895] msec_range[13] 0.200000 - 0.500000 : 3513 [20081217-08:27:49.273780718] msec_range[14] 0.100000 - 0.200000 : 23767 [20081217-08:27:49.276000453] msec_range[15] 0.050000 - 0.100000 : 79946 [20081217-08:27:49.278127785] msec_range[16] 0.020000 - 0.050000 : 255152 [20081217-08:27:49.280326526] msec_range[17] 0.010000 - 0.020000 : 4105460 [20081217-08:27:49.282566393] msec_range[18] 0.000000 - 0.010000 : 33849348 [20081217-08:27:49.285021229] [20081217-08:27:49.287429797] [ close] 0.001000 0.094089 40.473999 1501 [20081217-08:27:49.289951810] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-08:27:49.292437350] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-08:27:49.294667390] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-08:27:49.297049283] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-08:27:49.299231240] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-08:27:49.301412335] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-08:27:49.303531931] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-08:27:49.305805932] msec_range[7] 20.000000 - 50.000000 : 2 [20081217-08:27:49.308222649] msec_range[8] 10.000000 - 20.000000 : 2 [20081217-08:27:49.310683437] msec_range[9] 5.000000 - 10.000000 : 3 [20081217-08:27:49.313126446] msec_range[10] 2.000000 - 5.000000 : 3 [20081217-08:27:49.315406199] msec_range[11] 1.000000 - 2.000000 : 3 [20081217-08:27:49.317858265] msec_range[12] 0.500000 - 1.000000 : 2 [20081217-08:27:49.320267900] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-08:27:49.322586414] msec_range[14] 0.100000 - 0.200000 : 4 [20081217-08:27:49.324693547] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-08:27:49.326911240] msec_range[16] 0.020000 - 0.050000 : 9 [20081217-08:27:49.329028989] msec_range[17] 0.010000 - 0.020000 : 486 [20081217-08:27:49.331317882] msec_range[18] 0.000000 - 0.010000 : 987 [20081217-08:27:49.333539169] [20081217-08:27:49.335787464] [20081217-08:27:49.337885059] [20081217-08:27:49.340222292] [20081217-08:27:49.343153633] 11.7% User Time [20081217-08:27:49.345456124] 254.8% System Time [20081217-08:27:49.347604597] 266.5% CPU Utilization [20081217-08:27:49.350099432] Profilers reporting [20081217-08:28:08.859992416] Profilers postprocessing [20081217-08:28:09.996664951] Stopping profiling. [20081217-08:28:10.001936713] Killing daemon. [20081217-08:28:11.377075420] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0016.08-12-17_08.22.30/analysis/oprofile.001 [20081217-08:28:11.379347608] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0016.08-12-17_08.22.30/analysis/oprofile-brief.001 [20081217-08:28:11.602661740] Processing File : mpstat.001 [20081217-08:28:11.604744898] Discovered mpstat_interval=[5] [20081217-08:28:12.256440488] Processing Directory : sar.breakout.001 [20081217-08:28:12.258713748] Discovered sar_interval=[5] [20081217-08:28:12.577722857] Processing File : iostat.001 [20081217-08:28:12.579838510] Discovered iostat_interval=[5] [20081217-08:28:15.238791191] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0801/btrfs-baseline' [20081217-08:28:22.204178219] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-08:28:25.183926553] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-08:28:25.321566582] PROCESSING COMMAND : 'run sequential_reads__threads_0128 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb num_threads=128' [20081217-08:28:25.366029672] new log requested [20081217-08:28:25.389873654] Running command ffsb [20081217-08:28:34.537997623] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb [20081217-08:28:34.558274704] Importing argument : num_threads=128 [20081217-08:28:34.584636727] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-08:28:34.684361352] Checking for sar... [20081217-08:28:34.686445678] found [20081217-08:28:34.742254396] Checking for sar... [20081217-08:28:34.744361313] found [20081217-08:28:34.800187598] Checking for sar... [20081217-08:28:34.802406834] found [20081217-08:28:34.963973511] Checking for binutils-2.18 ... Already installed. [20081217-08:28:34.968373323] mv: cannot stat `lib64/*': No such file or directory [20081217-08:28:34.981014530] rmdir: lib64: No such file or directory [20081217-08:28:35.052190072] Checking for gettext-0.17 ... Already installed. [20081217-08:28:35.098594024] popt32-1.10.4 already installed. [20081217-08:28:35.113930524] popt64-1.10.4 already installed. [20081217-08:28:35.144150594] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-08:28:35.197508996] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-08:28:35.278868047] Daemon not running [20081217-08:28:35.368666503] Unloading oprofile module [20081217-08:28:35.567787427] Daemon not running [20081217-08:28:36.412464173] OPROFILE : using callgraph [5] [20081217-08:28:36.645433850] Daemon not running [20081217-08:28:36.647507306] Separate options: none [20081217-08:28:36.649488340] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-08:28:36.651683100] Image filter: none [20081217-08:28:36.653458209] Call-graph depth: 5 [20081217-08:28:36.743157677] FFSB version 6.0-RC2 started [20081217-08:28:36.745488375] [20081217-08:28:37.225376320] benchmark time = 300 [20081217-08:28:37.227829148] ThreadGroup 0 [20081217-08:28:37.229784793] ================ [20081217-08:28:37.231690913] num_threads = 128 [20081217-08:28:37.233474172] [20081217-08:28:37.235354801] read_random = off [20081217-08:28:37.237253173] read_size = 0 (0B) [20081217-08:28:37.239084041] read_blocksize = 4096 (4KB) [20081217-08:28:37.240848240] read_skip = off [20081217-08:28:37.242705774] read_skipsize = 0 (0B) [20081217-08:28:37.244438753] [20081217-08:28:37.246231054] write_random = off [20081217-08:28:37.247961997] write_size = 0 (0B) [20081217-08:28:37.249814058] fsync_file = 0 [20081217-08:28:37.251548894] write_blocksize = 0 (0B) [20081217-08:28:37.253367745] wait time = 0 [20081217-08:28:37.255103883] [20081217-08:28:37.256901832] op weights [20081217-08:28:37.258830010] read = 0 (0.00%) [20081217-08:28:37.260567092] readall = 1 (100.00%) [20081217-08:28:37.262462357] write = 0 (0.00%) [20081217-08:28:37.264282994] create = 0 (0.00%) [20081217-08:28:37.266142992] append = 0 (0.00%) [20081217-08:28:37.267861307] delete = 0 (0.00%) [20081217-08:28:37.269695319] metaop = 0 (0.00%) [20081217-08:28:37.271438196] createdir = 0 (0.00%) [20081217-08:28:37.273235560] stat = 0 (0.00%) [20081217-08:28:37.274985763] writeall = 0 (0.00%) [20081217-08:28:37.276763195] writeall_fsync = 0 (0.00%) [20081217-08:28:37.278790927] open_close = 0 (0.00%) [20081217-08:28:37.280620985] write_fsync = 0 (0.00%) [20081217-08:28:37.282356287] create_fsync = 0 (0.00%) [20081217-08:28:37.284367064] append_fsync = 0 (0.00%) [20081217-08:28:37.286156673] [20081217-08:28:37.287997948] FileSystem /mnt/ffsb1 [20081217-08:28:37.289742153] ========== [20081217-08:28:37.291534657] num_dirs = 0 [20081217-08:28:37.293310409] starting files = 1024 [20081217-08:28:37.295125671] [20081217-08:28:37.296889291] min file size = 104857600 (100MB) [20081217-08:28:37.298699548] max file size = 104857600 (100MB) [20081217-08:28:37.300772296] directio = off [20081217-08:28:37.302958136] alignedio = on [20081217-08:28:37.304888080] bufferedio = off [20081217-08:28:37.307073034] [20081217-08:28:37.309018988] aging is off [20081217-08:28:37.310858417] current utilization = 4.47% [20081217-08:28:37.312614177] [20081217-08:28:37.314550734] checking existing fs: /mnt/ffsb1 [20081217-08:28:37.546614984] fs setup took 0 secs [20081217-08:28:38.074387298] Syncing()...0 sec [20081217-08:28:38.080250154] Starting Actual Benchmark At: Wed Dec 17 08:28:38 2008 [20081217-08:28:38.093077484] [20081217-08:33:57.113151197] Syncing()...1 sec [20081217-08:33:57.178834559] FFSB benchmark finished at: Wed Dec 17 08:33:56 2008 [20081217-08:33:57.181777128] [20081217-08:33:57.184490986] Results: [20081217-08:33:57.226421495] Benchmark took 318.66 sec [20081217-08:33:57.229106171] [20081217-08:33:57.231428688] Total Results [20081217-08:33:57.246474913] =============== [20081217-08:33:57.248425107] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-08:33:57.250649968] ======= ============ ========= ======= =========== ========== [20081217-08:33:57.252974425] readall : 30003200 94153.34 100.000% 100.000% 368MB/sec [20081217-08:33:57.255142309] - [20081217-08:33:57.257128886] 94153.34 Transactions per Second [20081217-08:33:57.259583872] [20081217-08:33:57.262024495] Throughput Results [20081217-08:33:57.276714582] =================== [20081217-08:33:57.278778064] Read Throughput: 368MB/sec [20081217-08:33:57.280939106] [20081217-08:33:57.283192706] System Call Latency statistics in millisecs [20081217-08:33:57.285420995] ===== [20081217-08:33:57.287617975] Min Avg Max Total Calls [20081217-08:33:57.290149247] ======== ======== ======== ============ [20081217-08:33:57.292427472] [ open] 0.006000 13.510137 1043.928955 1172 [20081217-08:33:57.294423179] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-08:33:57.296495841] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-08:33:57.298892998] msec_range[2] 1000.000000 - 2000.000000 : 1 [20081217-08:33:57.301188402] msec_range[3] 500.000000 - 1000.000000 : 11 [20081217-08:33:57.303313240] msec_range[4] 200.000000 - 500.000000 : 10 [20081217-08:33:57.305315689] msec_range[5] 100.000000 - 200.000000 : 16 [20081217-08:33:57.307495703] msec_range[6] 50.000000 - 100.000000 : 13 [20081217-08:33:57.309597715] msec_range[7] 20.000000 - 50.000000 : 30 [20081217-08:33:57.311531317] msec_range[8] 10.000000 - 20.000000 : 21 [20081217-08:33:57.313521658] msec_range[9] 5.000000 - 10.000000 : 19 [20081217-08:33:57.315691208] msec_range[10] 2.000000 - 5.000000 : 9 [20081217-08:33:57.317793880] msec_range[11] 1.000000 - 2.000000 : 1 [20081217-08:33:57.319737005] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-08:33:57.321735049] msec_range[13] 0.200000 - 0.500000 : 3 [20081217-08:33:57.323898395] msec_range[14] 0.100000 - 0.200000 : 222 [20081217-08:33:57.325980792] msec_range[15] 0.050000 - 0.100000 : 260 [20081217-08:33:57.328211108] msec_range[16] 0.020000 - 0.050000 : 438 [20081217-08:33:57.330542645] msec_range[17] 0.010000 - 0.020000 : 72 [20081217-08:33:57.332696274] msec_range[18] 0.000000 - 0.010000 : 46 [20081217-08:33:57.334882721] [20081217-08:33:57.336934017] [ read] 0.001000 1.327398 6838.208008 30003200 [20081217-08:33:57.355123811] msec_range[0] 5000.000000 - 10000.000000 : 7 [20081217-08:33:57.357736749] msec_range[1] 2000.000000 - 5000.000000 : 1751 [20081217-08:33:57.360135938] msec_range[2] 1000.000000 - 2000.000000 : 10665 [20081217-08:33:57.362410024] msec_range[3] 500.000000 - 1000.000000 : 16251 [20081217-08:33:57.364560437] msec_range[4] 200.000000 - 500.000000 : 16996 [20081217-08:33:57.366784143] msec_range[5] 100.000000 - 200.000000 : 12071 [20081217-08:33:57.368903467] msec_range[6] 50.000000 - 100.000000 : 10795 [20081217-08:33:57.370905032] msec_range[7] 20.000000 - 50.000000 : 13090 [20081217-08:33:57.372911989] msec_range[8] 10.000000 - 20.000000 : 6830 [20081217-08:33:57.375204428] msec_range[9] 5.000000 - 10.000000 : 5033 [20081217-08:33:57.377613294] msec_range[10] 2.000000 - 5.000000 : 4422 [20081217-08:33:57.379854302] msec_range[11] 1.000000 - 2.000000 : 2895 [20081217-08:33:57.382207072] msec_range[12] 0.500000 - 1.000000 : 2578 [20081217-08:33:57.384428200] msec_range[13] 0.200000 - 0.500000 : 65280 [20081217-08:33:57.386538921] msec_range[14] 0.100000 - 0.200000 : 178661 [20081217-08:33:57.388694058] msec_range[15] 0.050000 - 0.100000 : 60771 [20081217-08:33:57.391053628] msec_range[16] 0.020000 - 0.050000 : 121858 [20081217-08:33:57.393164163] msec_range[17] 0.010000 - 0.020000 : 4877592 [20081217-08:33:57.395154552] msec_range[18] 0.000000 - 0.010000 : 24595654 [20081217-08:33:57.397179093] [20081217-08:33:57.399401818] [ close] 0.002000 0.009759 0.025000 1172 [20081217-08:33:57.401517918] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-08:33:57.403825352] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-08:33:57.406529800] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-08:33:57.408962976] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-08:33:57.411358409] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-08:33:57.413469895] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-08:33:57.415697098] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-08:33:57.417907529] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-08:33:57.419927390] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-08:33:57.422028591] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-08:33:57.424249607] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-08:33:57.427014114] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-08:33:57.429703758] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-08:33:57.432137310] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-08:33:57.434465410] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-08:33:57.436864990] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-08:33:57.439317800] msec_range[16] 0.020000 - 0.050000 : 3 [20081217-08:33:57.441622646] msec_range[17] 0.010000 - 0.020000 : 467 [20081217-08:33:57.443925685] msec_range[18] 0.000000 - 0.010000 : 702 [20081217-08:33:57.446219635] [20081217-08:33:57.448463893] [20081217-08:33:57.450565990] [20081217-08:33:57.452780890] [20081217-08:33:57.454938915] 11.1% User Time [20081217-08:33:57.457165799] 911.7% System Time [20081217-08:33:57.459328019] 922.8% CPU Utilization [20081217-08:33:57.471981287] Profilers reporting [20081217-08:34:13.684442297] Profilers postprocessing [20081217-08:34:14.822563749] Stopping profiling. [20081217-08:34:14.827447854] Killing daemon. [20081217-08:34:17.403885215] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0128.08-12-17_08.28.25/analysis/oprofile.001 [20081217-08:34:17.406151404] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0128.08-12-17_08.28.25/analysis/oprofile-brief.001 [20081217-08:34:17.665624386] Processing File : mpstat.001 [20081217-08:34:17.668074384] Discovered mpstat_interval=[5] [20081217-08:34:18.308978228] Processing Directory : sar.breakout.001 [20081217-08:34:18.311227166] Discovered sar_interval=[5] [20081217-08:34:18.640396974] Processing File : iostat.001 [20081217-08:34:18.642553322] Discovered iostat_interval=[5] [20081217-08:34:20.703259231] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0801/btrfs-baseline' [20081217-08:34:30.492598848] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-08:34:33.656263231] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-08:34:33.776765642] PROCESSING COMMAND : 'run random_reads__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb num_threads=1' [20081217-08:34:33.821329598] new log requested [20081217-08:34:33.845420291] Running command ffsb [20081217-08:34:43.576921676] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb [20081217-08:34:43.593071740] Importing argument : num_threads=1 [20081217-08:34:43.618831351] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-08:34:43.719330792] Checking for sar... [20081217-08:34:43.721528683] found [20081217-08:34:43.777917565] Checking for sar... [20081217-08:34:43.814241070] found [20081217-08:34:43.836024507] Checking for sar... [20081217-08:34:43.838115766] found [20081217-08:34:43.993116096] Checking for binutils-2.18 ... Already installed. [20081217-08:34:43.997565546] mv: cannot stat `lib64/*': No such file or directory [20081217-08:34:44.010179164] rmdir: lib64: No such file or directory [20081217-08:34:44.081275852] Checking for gettext-0.17 ... Already installed. [20081217-08:34:44.127868150] popt32-1.10.4 already installed. [20081217-08:34:44.142963517] popt64-1.10.4 already installed. [20081217-08:34:44.173996345] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-08:34:44.227197648] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-08:34:44.308186450] Daemon not running [20081217-08:34:44.325839576] Unloading oprofile module [20081217-08:34:44.513403488] Daemon not running [20081217-08:34:45.201735083] OPROFILE : using callgraph [5] [20081217-08:34:45.435622917] Daemon not running [20081217-08:34:45.437582875] Separate options: none [20081217-08:34:45.439761376] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-08:34:45.441873190] Image filter: none [20081217-08:34:45.443748608] Call-graph depth: 5 [20081217-08:34:45.530133239] FFSB version 6.0-RC2 started [20081217-08:34:45.532144436] [20081217-08:34:45.534108663] benchmark time = 300 [20081217-08:34:45.536248343] ThreadGroup 0 [20081217-08:34:45.538139030] ================ [20081217-08:34:45.540298127] num_threads = 1 [20081217-08:34:45.542272475] [20081217-08:34:45.544512525] read_random = on [20081217-08:34:45.546465557] read_size = 5242880 (5MB) [20081217-08:34:45.548344653] read_blocksize = 4096 (4KB) [20081217-08:34:45.550106726] read_skip = off [20081217-08:34:45.551972126] read_skipsize = 0 (0B) [20081217-08:34:45.553775995] [20081217-08:34:45.555667620] write_random = off [20081217-08:34:45.557442806] write_size = 0 (0B) [20081217-08:34:45.559377458] fsync_file = 0 [20081217-08:34:45.561316126] write_blocksize = 0 (0B) [20081217-08:34:45.563191388] wait time = 0 [20081217-08:34:45.564931567] [20081217-08:34:45.566723133] op weights [20081217-08:34:45.568545953] read = 1 (100.00%) [20081217-08:34:45.570367447] readall = 0 (0.00%) [20081217-08:34:45.572091614] write = 0 (0.00%) [20081217-08:34:45.573969861] create = 0 (0.00%) [20081217-08:34:45.575768874] append = 0 (0.00%) [20081217-08:34:45.577603048] delete = 0 (0.00%) [20081217-08:34:45.579329551] metaop = 0 (0.00%) [20081217-08:34:45.581176126] createdir = 0 (0.00%) [20081217-08:34:45.583022354] stat = 0 (0.00%) [20081217-08:34:45.585065208] writeall = 0 (0.00%) [20081217-08:34:45.586848921] writeall_fsync = 0 (0.00%) [20081217-08:34:45.588757879] open_close = 0 (0.00%) [20081217-08:34:45.590617535] write_fsync = 0 (0.00%) [20081217-08:34:45.592456605] create_fsync = 0 (0.00%) [20081217-08:34:45.594186298] append_fsync = 0 (0.00%) [20081217-08:34:45.596090646] [20081217-08:34:45.597870975] FileSystem /mnt/ffsb1 [20081217-08:34:45.599737730] ========== [20081217-08:34:45.601488814] num_dirs = 0 [20081217-08:34:45.603346744] starting files = 1024 [20081217-08:34:45.605096812] [20081217-08:34:45.606900930] min file size = 104857600 (100MB) [20081217-08:34:45.608646355] max file size = 104857600 (100MB) [20081217-08:34:45.610677479] directio = off [20081217-08:34:45.612716227] alignedio = on [20081217-08:34:45.614550364] bufferedio = off [20081217-08:34:45.616508945] [20081217-08:34:45.618389749] aging is off [20081217-08:34:45.620317097] current utilization = 4.47% [20081217-08:34:45.622101233] [20081217-08:34:45.624518467] checking existing fs: /mnt/ffsb1 [20081217-08:34:45.847853858] fs setup took 0 secs [20081217-08:34:46.320280024] Syncing()...0 sec [20081217-08:34:46.322222899] Starting Actual Benchmark At: Wed Dec 17 08:34:46 2008 [20081217-08:34:46.335387212] [20081217-08:39:51.817098057] Syncing()...2 sec [20081217-08:39:51.820073166] FFSB benchmark finished at: Wed Dec 17 08:39:51 2008 [20081217-08:39:51.822967479] [20081217-08:39:51.825796431] Results: [20081217-08:39:51.841191925] Benchmark took 305.50 sec [20081217-08:39:51.843815036] [20081217-08:39:51.846324693] Total Results [20081217-08:39:51.861607039] =============== [20081217-08:39:51.864662349] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-08:39:51.867251773] ======= ============ ========= ======= =========== ========== [20081217-08:39:51.870107141] read : 161280 527.93 100.000% 100.000% 2.06MB/sec [20081217-08:39:51.872748109] - [20081217-08:39:51.875392424] 527.93 Transactions per Second [20081217-08:39:51.877815004] [20081217-08:39:51.880971125] Throughput Results [20081217-08:39:51.899282519] =================== [20081217-08:39:51.901908066] Read Throughput: 2.06MB/sec [20081217-08:39:51.904567372] [20081217-08:39:51.907132952] System Call Latency statistics in millisecs [20081217-08:39:51.910650503] ===== [20081217-08:39:51.913309146] Min Avg Max Total Calls [20081217-08:39:51.916293715] ======== ======== ======== ============ [20081217-08:39:51.921014027] [ open] 0.013000 0.025310 0.038000 126 [20081217-08:39:51.923598568] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-08:39:51.928489971] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-08:39:51.930981152] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-08:39:51.933426717] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-08:39:51.935846287] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-08:39:51.938657101] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-08:39:51.942541674] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-08:39:51.946747405] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-08:39:51.949599775] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-08:39:51.952493883] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-08:39:51.955671542] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-08:39:51.958604795] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-08:39:51.961606886] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-08:39:51.964517843] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-08:39:51.966978159] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-08:39:51.969377939] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-08:39:51.971816000] msec_range[16] 0.020000 - 0.050000 : 122 [20081217-08:39:51.974678547] msec_range[17] 0.010000 - 0.020000 : 4 [20081217-08:39:51.978333205] msec_range[18] 0.000000 - 0.010000 : 0 [20081217-08:39:51.981552416] [20081217-08:39:51.984638275] [ read] 0.002000 1.876149 38.820999 161280 [20081217-08:39:51.987158398] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-08:39:51.989684408] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-08:39:51.992496626] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-08:39:51.995339190] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-08:39:51.997976648] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-08:39:52.001056856] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-08:39:52.003481189] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-08:39:52.006852281] msec_range[7] 20.000000 - 50.000000 : 97 [20081217-08:39:52.011018489] msec_range[8] 10.000000 - 20.000000 : 872 [20081217-08:39:52.013992687] msec_range[9] 5.000000 - 10.000000 : 13974 [20081217-08:39:52.016991756] msec_range[10] 2.000000 - 5.000000 : 41129 [20081217-08:39:52.020274267] msec_range[11] 1.000000 - 2.000000 : 8729 [20081217-08:39:52.022941620] msec_range[12] 0.500000 - 1.000000 : 650 [20081217-08:39:52.025528086] msec_range[13] 0.200000 - 0.500000 : 91299 [20081217-08:39:52.027972865] msec_range[14] 0.100000 - 0.200000 : 26 [20081217-08:39:52.030523034] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-08:39:52.033182872] msec_range[16] 0.020000 - 0.050000 : 27 [20081217-08:39:52.035343105] msec_range[17] 0.010000 - 0.020000 : 652 [20081217-08:39:52.037463539] msec_range[18] 0.000000 - 0.010000 : 3825 [20081217-08:39:52.040190551] [20081217-08:39:52.042829732] [ lseek] 0.000000 0.001406 0.221000 161280 [20081217-08:39:52.046563458] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-08:39:52.049382112] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-08:39:52.053494960] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-08:39:52.055956741] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-08:39:52.058380654] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-08:39:52.061108791] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-08:39:52.063876420] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-08:39:52.066516258] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-08:39:52.069123002] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-08:39:52.071275613] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-08:39:52.074062594] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-08:39:52.076686371] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-08:39:52.079433927] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-08:39:52.082072602] msec_range[13] 0.200000 - 0.500000 : 1 [20081217-08:39:52.084728115] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-08:39:52.087589923] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-08:39:52.089842330] msec_range[16] 0.020000 - 0.050000 : 1 [20081217-08:39:52.092485618] msec_range[17] 0.010000 - 0.020000 : 75 [20081217-08:39:52.095077019] msec_range[18] 0.000000 - 0.010000 : 161203 [20081217-08:39:52.097654869] [20081217-08:39:52.100223148] [ close] 0.004000 0.006690 0.015000 126 [20081217-08:39:52.102622683] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-08:39:52.105162857] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-08:39:52.107722290] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-08:39:52.110094889] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-08:39:52.112788770] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-08:39:52.115442490] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-08:39:52.117933519] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-08:39:52.120925294] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-08:39:52.123345853] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-08:39:52.125636281] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-08:39:52.128128706] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-08:39:52.130797000] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-08:39:52.133252931] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-08:39:52.135660813] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-08:39:52.138183088] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-08:39:52.140726593] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-08:39:52.142976191] msec_range[16] 0.020000 - 0.050000 : 0 [20081217-08:39:52.145200066] msec_range[17] 0.010000 - 0.020000 : 15 [20081217-08:39:52.147484228] msec_range[18] 0.000000 - 0.010000 : 111 [20081217-08:39:52.150181578] [20081217-08:39:52.152680221] [20081217-08:39:52.155882507] [20081217-08:39:52.158253720] [20081217-08:39:52.160894979] 0.1% User Time [20081217-08:39:52.163158876] 3.6% System Time [20081217-08:39:52.165347814] 3.7% CPU Utilization [20081217-08:39:52.167691604] Profilers reporting [20081217-08:40:06.904230610] Profilers postprocessing [20081217-08:40:08.042107603] Stopping profiling. [20081217-08:40:08.047503642] Killing daemon. [20081217-08:40:09.224065272] Processing File : /autobench/logs/ffsb.random_reads__threads_0001.08-12-17_08.34.33/analysis/oprofile.001 [20081217-08:40:09.226274961] Processing File : /autobench/logs/ffsb.random_reads__threads_0001.08-12-17_08.34.33/analysis/oprofile-brief.001 [20081217-08:40:09.342581776] Processing File : mpstat.001 [20081217-08:40:09.344760025] Discovered mpstat_interval=[5] [20081217-08:40:09.895644968] Processing Directory : sar.breakout.001 [20081217-08:40:09.897862627] Discovered sar_interval=[5] [20081217-08:40:10.036868903] Processing File : iostat.001 [20081217-08:40:10.039238584] Discovered iostat_interval=[5] [20081217-08:40:11.491133066] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0801/btrfs-baseline' [20081217-08:40:16.561702932] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-08:40:17.344622751] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-08:40:17.476090493] PROCESSING COMMAND : 'run random_reads__threads_0016 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb num_threads=16' [20081217-08:40:17.520665183] new log requested [20081217-08:40:17.545150839] Running command ffsb [20081217-08:40:26.026545715] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb [20081217-08:40:26.041256101] Importing argument : num_threads=16 [20081217-08:40:26.067003412] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-08:40:26.155732421] Checking for sar... [20081217-08:40:26.158116724] found [20081217-08:40:26.214617226] Checking for sar... [20081217-08:40:26.216786618] found [20081217-08:40:26.272588523] Checking for sar... [20081217-08:40:26.274936987] found [20081217-08:40:26.403906393] Checking for binutils-2.18 ... Already installed. [20081217-08:40:26.408208385] mv: cannot stat `lib64/*': No such file or directory [20081217-08:40:26.411088285] rmdir: lib64: No such file or directory [20081217-08:40:26.470477071] Checking for gettext-0.17 ... Already installed. [20081217-08:40:26.512058279] popt32-1.10.4 already installed. [20081217-08:40:26.527076113] popt64-1.10.4 already installed. [20081217-08:40:26.557997408] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-08:40:26.610004042] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-08:40:26.691057060] Daemon not running [20081217-08:40:26.701639761] Unloading oprofile module [20081217-08:40:26.810372659] Daemon not running [20081217-08:40:27.709048345] OPROFILE : using callgraph [5] [20081217-08:40:27.943280506] Daemon not running [20081217-08:40:27.945319728] Separate options: none [20081217-08:40:27.947503040] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-08:40:27.949573423] Image filter: none [20081217-08:40:27.951639407] Call-graph depth: 5 [20081217-08:40:28.010586601] FFSB version 6.0-RC2 started [20081217-08:40:28.012694451] [20081217-08:40:28.071917338] benchmark time = 300 [20081217-08:40:28.073936555] ThreadGroup 0 [20081217-08:40:28.075822071] ================ [20081217-08:40:28.077809874] num_threads = 16 [20081217-08:40:28.079978589] [20081217-08:40:28.082745128] read_random = on [20081217-08:40:28.084592935] read_size = 5242880 (5MB) [20081217-08:40:28.086406933] read_blocksize = 4096 (4KB) [20081217-08:40:28.088501468] read_skip = off [20081217-08:40:28.090580311] read_skipsize = 0 (0B) [20081217-08:40:28.092617167] [20081217-08:40:28.094582842] write_random = off [20081217-08:40:28.096543908] write_size = 0 (0B) [20081217-08:40:28.098293118] fsync_file = 0 [20081217-08:40:28.100154951] write_blocksize = 0 (0B) [20081217-08:40:28.101996557] wait time = 0 [20081217-08:40:28.103874321] [20081217-08:40:28.105787383] op weights [20081217-08:40:28.107618226] read = 1 (100.00%) [20081217-08:40:28.109647304] readall = 0 (0.00%) [20081217-08:40:28.111603756] write = 0 (0.00%) [20081217-08:40:28.113481269] create = 0 (0.00%) [20081217-08:40:28.115325320] append = 0 (0.00%) [20081217-08:40:28.117206301] delete = 0 (0.00%) [20081217-08:40:28.118906654] metaop = 0 (0.00%) [20081217-08:40:28.120787229] createdir = 0 (0.00%) [20081217-08:40:28.122600126] stat = 0 (0.00%) [20081217-08:40:28.124460882] writeall = 0 (0.00%) [20081217-08:40:28.126194713] writeall_fsync = 0 (0.00%) [20081217-08:40:28.128053722] open_close = 0 (0.00%) [20081217-08:40:28.129864695] write_fsync = 0 (0.00%) [20081217-08:40:28.131680817] create_fsync = 0 (0.00%) [20081217-08:40:28.133445095] append_fsync = 0 (0.00%) [20081217-08:40:28.135277742] [20081217-08:40:28.137074365] FileSystem /mnt/ffsb1 [20081217-08:40:28.138919715] ========== [20081217-08:40:28.140635139] num_dirs = 0 [20081217-08:40:28.142446281] starting files = 1024 [20081217-08:40:28.144170246] [20081217-08:40:28.145979006] min file size = 104857600 (100MB) [20081217-08:40:28.147715186] max file size = 104857600 (100MB) [20081217-08:40:28.149645252] directio = off [20081217-08:40:28.151746378] alignedio = on [20081217-08:40:28.153589469] bufferedio = off [20081217-08:40:28.155560130] [20081217-08:40:28.157435896] aging is off [20081217-08:40:28.159262904] current utilization = 4.47% [20081217-08:40:28.161033534] [20081217-08:40:28.162863925] checking existing fs: /mnt/ffsb1 [20081217-08:40:28.378833479] fs setup took 0 secs [20081217-08:40:28.941421937] Syncing()...0 sec [20081217-08:40:28.943546305] Starting Actual Benchmark At: Wed Dec 17 08:40:28 2008 [20081217-08:40:28.957864119] [20081217-08:45:37.610316227] Syncing()...4 sec [20081217-08:45:37.618693142] FFSB benchmark finished at: Wed Dec 17 08:45:37 2008 [20081217-08:45:37.621538300] [20081217-08:45:37.624299822] Results: [20081217-08:45:37.641430740] Benchmark took 308.67 sec [20081217-08:45:37.644231991] [20081217-08:45:37.647364924] Total Results [20081217-08:45:37.663496697] =============== [20081217-08:45:37.666171141] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-08:45:37.668708246] ======= ============ ========= ======= =========== ========== [20081217-08:45:37.671358824] read : 1501440 4864.29 100.000% 100.000% 19MB/sec [20081217-08:45:37.674038453] - [20081217-08:45:37.676733503] 4864.29 Transactions per Second [20081217-08:45:37.679411785] [20081217-08:45:37.682649941] Throughput Results [20081217-08:45:37.699519694] =================== [20081217-08:45:37.702314771] Read Throughput: 19MB/sec [20081217-08:45:37.705078605] [20081217-08:45:37.709796063] System Call Latency statistics in millisecs [20081217-08:45:37.712715249] ===== [20081217-08:45:37.715230393] Min Avg Max Total Calls [20081217-08:45:37.717778347] ======== ======== ======== ============ [20081217-08:45:37.722977060] [ open] 0.008000 0.028471 0.109000 1173 [20081217-08:45:37.726533381] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-08:45:37.732603942] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-08:45:37.735686562] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-08:45:37.738400678] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-08:45:37.741474323] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-08:45:37.744369001] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-08:45:37.748245519] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-08:45:37.751179535] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-08:45:37.754352256] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-08:45:37.757181646] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-08:45:37.759982308] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-08:45:37.762592745] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-08:45:37.765170509] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-08:45:37.767964175] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-08:45:37.770873309] msec_range[14] 0.100000 - 0.200000 : 1 [20081217-08:45:37.773726147] msec_range[15] 0.050000 - 0.100000 : 66 [20081217-08:45:37.776614389] msec_range[16] 0.020000 - 0.050000 : 1020 [20081217-08:45:37.779421051] msec_range[17] 0.010000 - 0.020000 : 74 [20081217-08:45:37.783405264] msec_range[18] 0.000000 - 0.010000 : 12 [20081217-08:45:37.786346650] [20081217-08:45:37.789372758] [ read] 0.001000 3.219724 57.223000 1501440 [20081217-08:45:37.791942325] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-08:45:37.794431160] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-08:45:37.796848974] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-08:45:37.799546791] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-08:45:37.801986807] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-08:45:37.804193491] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-08:45:37.809167323] msec_range[6] 50.000000 - 100.000000 : 16 [20081217-08:45:37.812211877] msec_range[7] 20.000000 - 50.000000 : 521 [20081217-08:45:37.815033102] msec_range[8] 10.000000 - 20.000000 : 9290 [20081217-08:45:37.820491216] msec_range[9] 5.000000 - 10.000000 : 304423 [20081217-08:45:37.823850305] msec_range[10] 2.000000 - 5.000000 : 744383 [20081217-08:45:37.827046480] msec_range[11] 1.000000 - 2.000000 : 60304 [20081217-08:45:37.830217952] msec_range[12] 0.500000 - 1.000000 : 50956 [20081217-08:45:37.833167063] msec_range[13] 0.200000 - 0.500000 : 254279 [20081217-08:45:37.836009262] msec_range[14] 0.100000 - 0.200000 : 46 [20081217-08:45:37.838981694] msec_range[15] 0.050000 - 0.100000 : 42 [20081217-08:45:37.841605939] msec_range[16] 0.020000 - 0.050000 : 1490 [20081217-08:45:37.844113472] msec_range[17] 0.010000 - 0.020000 : 16189 [20081217-08:45:37.846458966] msec_range[18] 0.000000 - 0.010000 : 59501 [20081217-08:45:37.850321524] [20081217-08:45:37.854478320] [ lseek] 0.000000 0.001559 0.491000 1501440 [20081217-08:45:37.858962263] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-08:45:37.862800854] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-08:45:37.865714371] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-08:45:37.869329287] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-08:45:37.872085357] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-08:45:37.874929600] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-08:45:37.877905893] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-08:45:37.880318335] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-08:45:37.882977755] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-08:45:37.896257083] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-08:45:37.899600595] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-08:45:37.902261102] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-08:45:37.905053841] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-08:45:37.908225181] msec_range[13] 0.200000 - 0.500000 : 12 [20081217-08:45:37.910922920] msec_range[14] 0.100000 - 0.200000 : 14 [20081217-08:45:37.913658234] msec_range[15] 0.050000 - 0.100000 : 33 [20081217-08:45:37.916366986] msec_range[16] 0.020000 - 0.050000 : 257 [20081217-08:45:37.919142489] msec_range[17] 0.010000 - 0.020000 : 1103 [20081217-08:45:37.921862422] msec_range[18] 0.000000 - 0.010000 : 1500021 [20081217-08:45:37.924163926] [20081217-08:45:37.926745509] [ close] 0.002000 0.007276 0.095000 1173 [20081217-08:45:37.929144842] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-08:45:37.931648011] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-08:45:37.933914428] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-08:45:37.936355163] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-08:45:37.938767625] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-08:45:37.941019501] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-08:45:37.943333268] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-08:45:37.945621987] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-08:45:37.947904641] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-08:45:37.950110675] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-08:45:37.952471097] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-08:45:37.954815757] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-08:45:37.957075899] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-08:45:37.959399261] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-08:45:37.961710654] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-08:45:37.963849823] msec_range[15] 0.050000 - 0.100000 : 1 [20081217-08:45:37.966138872] msec_range[16] 0.020000 - 0.050000 : 1 [20081217-08:45:37.968341095] msec_range[17] 0.010000 - 0.020000 : 216 [20081217-08:45:37.970621298] msec_range[18] 0.000000 - 0.010000 : 955 [20081217-08:45:37.972832707] [20081217-08:45:37.975207939] [20081217-08:45:37.977532965] [20081217-08:45:37.981101397] [20081217-08:45:37.983386264] 1.5% User Time [20081217-08:45:37.985611156] 40.6% System Time [20081217-08:45:37.987871661] 42.1% CPU Utilization [20081217-08:45:37.990028105] Profilers reporting [20081217-08:45:55.829669837] Profilers postprocessing [20081217-08:45:56.966113918] Stopping profiling. [20081217-08:45:56.971417737] Killing daemon. [20081217-08:45:59.220660082] Processing File : /autobench/logs/ffsb.random_reads__threads_0016.08-12-17_08.40.17/analysis/oprofile.001 [20081217-08:45:59.222884547] Processing File : /autobench/logs/ffsb.random_reads__threads_0016.08-12-17_08.40.17/analysis/oprofile-brief.001 [20081217-08:45:59.347227583] Processing File : mpstat.001 [20081217-08:45:59.349635924] Discovered mpstat_interval=[5] [20081217-08:45:59.931173660] Processing Directory : sar.breakout.001 [20081217-08:45:59.933453731] Discovered sar_interval=[5] [20081217-08:46:00.100408061] Processing File : iostat.001 [20081217-08:46:00.102596194] Discovered iostat_interval=[5] [20081217-08:46:01.658307596] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0801/btrfs-baseline' [20081217-08:46:06.408525846] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-08:46:10.330604820] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-08:46:10.453873349] PROCESSING COMMAND : 'run random_reads__threads_0128 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb num_threads=128' [20081217-08:46:10.498803361] new log requested [20081217-08:46:10.522613201] Running command ffsb [20081217-08:46:19.109155641] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb [20081217-08:46:19.123761532] Importing argument : num_threads=128 [20081217-08:46:19.149271619] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-08:46:19.237719523] Checking for sar... [20081217-08:46:19.239808983] found [20081217-08:46:19.295803024] Checking for sar... [20081217-08:46:19.297999289] found [20081217-08:46:19.353797962] Checking for sar... [20081217-08:46:19.356251102] found [20081217-08:46:19.501876714] Checking for binutils-2.18 ... Already installed. [20081217-08:46:19.506069577] mv: cannot stat `lib64/*': No such file or directory [20081217-08:46:19.509272780] rmdir: lib64: No such file or directory [20081217-08:46:19.569078150] Checking for gettext-0.17 ... Already installed. [20081217-08:46:19.610134833] popt32-1.10.4 already installed. [20081217-08:46:19.625294149] popt64-1.10.4 already installed. [20081217-08:46:19.656145894] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-08:46:19.708622157] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-08:46:19.788626618] Daemon not running [20081217-08:46:19.799205355] Unloading oprofile module [20081217-08:46:19.912599219] Daemon not running [20081217-08:46:20.929496698] OPROFILE : using callgraph [5] [20081217-08:46:21.162904656] Daemon not running [20081217-08:46:21.165078523] Separate options: none [20081217-08:46:21.167115938] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-08:46:21.169219305] Image filter: none [20081217-08:46:21.171185933] Call-graph depth: 5 [20081217-08:46:21.230432927] FFSB version 6.0-RC2 started [20081217-08:46:21.232682062] [20081217-08:46:21.723858024] benchmark time = 300 [20081217-08:46:21.726142226] ThreadGroup 0 [20081217-08:46:21.728034269] ================ [20081217-08:46:21.729792283] num_threads = 128 [20081217-08:46:21.731904822] [20081217-08:46:21.733857622] read_random = on [20081217-08:46:21.735703200] read_size = 5242880 (5MB) [20081217-08:46:21.737456679] read_blocksize = 4096 (4KB) [20081217-08:46:21.739779118] read_skip = off [20081217-08:46:21.741662704] read_skipsize = 0 (0B) [20081217-08:46:21.743482136] [20081217-08:46:21.745175882] write_random = off [20081217-08:46:21.747042374] write_size = 0 (0B) [20081217-08:46:21.748851379] fsync_file = 0 [20081217-08:46:21.750692152] write_blocksize = 0 (0B) [20081217-08:46:21.752409315] wait time = 0 [20081217-08:46:21.754289329] [20081217-08:46:21.756040305] op weights [20081217-08:46:21.757843475] read = 1 (100.00%) [20081217-08:46:21.759571720] readall = 0 (0.00%) [20081217-08:46:21.761401209] write = 0 (0.00%) [20081217-08:46:21.763131394] create = 0 (0.00%) [20081217-08:46:21.764947305] append = 0 (0.00%) [20081217-08:46:21.766664845] delete = 0 (0.00%) [20081217-08:46:21.768611543] metaop = 0 (0.00%) [20081217-08:46:21.770484703] createdir = 0 (0.00%) [20081217-08:46:21.772340415] stat = 0 (0.00%) [20081217-08:46:21.774083546] writeall = 0 (0.00%) [20081217-08:46:21.775924441] writeall_fsync = 0 (0.00%) [20081217-08:46:21.777703433] open_close = 0 (0.00%) [20081217-08:46:21.779502176] write_fsync = 0 (0.00%) [20081217-08:46:21.781210302] create_fsync = 0 (0.00%) [20081217-08:46:21.783191579] append_fsync = 0 (0.00%) [20081217-08:46:21.785460751] [20081217-08:46:21.787477019] FileSystem /mnt/ffsb1 [20081217-08:46:21.789747595] ========== [20081217-08:46:21.791801614] num_dirs = 0 [20081217-08:46:21.793563711] starting files = 1024 [20081217-08:46:21.795442714] [20081217-08:46:21.797336603] min file size = 104857600 (100MB) [20081217-08:46:21.799210927] max file size = 104857600 (100MB) [20081217-08:46:21.800950254] directio = off [20081217-08:46:21.802753800] alignedio = on [20081217-08:46:21.804517728] bufferedio = off [20081217-08:46:21.806316138] [20081217-08:46:21.808050316] aging is off [20081217-08:46:21.809866526] current utilization = 4.47% [20081217-08:46:21.811618509] [20081217-08:46:21.813393436] checking existing fs: /mnt/ffsb1 [20081217-08:46:22.067578862] fs setup took 0 secs [20081217-08:46:22.890076923] Syncing()...0 sec [20081217-08:46:22.895400003] Starting Actual Benchmark At: Wed Dec 17 08:46:22 2008 [20081217-08:46:22.908407363] [20081217-08:51:32.874262560] Syncing()...3 sec [20081217-08:51:32.916759058] FFSB benchmark finished at: Wed Dec 17 08:51:32 2008 [20081217-08:51:32.919437632] [20081217-08:51:32.921962823] Results: [20081217-08:51:32.988902051] Benchmark took 309.73 sec [20081217-08:51:32.990870236] [20081217-08:51:32.993440418] Total Results [20081217-08:51:33.008919432] =============== [20081217-08:51:33.011544439] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-08:51:33.014224488] ======= ============ ========= ======= =========== ========== [20081217-08:51:33.016595259] read : 6579200 21241.92 100.000% 100.000% 83MB/sec [20081217-08:51:33.018886959] - [20081217-08:51:33.021166543] 21241.92 Transactions per Second [20081217-08:51:33.023251601] [20081217-08:51:33.025597039] Throughput Results [20081217-08:51:33.040316356] =================== [20081217-08:51:33.042297872] Read Throughput: 83MB/sec [20081217-08:51:33.044830521] [20081217-08:51:33.047245844] System Call Latency statistics in millisecs [20081217-08:51:33.049549547] ===== [20081217-08:51:33.052049401] Min Avg Max Total Calls [20081217-08:51:33.054425697] ======== ======== ======== ============ [20081217-08:51:33.056902811] [ open] 0.007000 0.050782 33.765999 5140 [20081217-08:51:33.059214421] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-08:51:33.061445693] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-08:51:33.063625882] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-08:51:33.098521339] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-08:51:33.100910091] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-08:51:33.102985207] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-08:51:33.105091470] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-08:51:33.107213687] msec_range[7] 20.000000 - 50.000000 : 1 [20081217-08:51:33.109426592] msec_range[8] 10.000000 - 20.000000 : 1 [20081217-08:51:33.111528136] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-08:51:33.113679960] msec_range[10] 2.000000 - 5.000000 : 1 [20081217-08:51:33.115802500] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-08:51:33.118028494] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-08:51:33.120104202] msec_range[13] 0.200000 - 0.500000 : 19 [20081217-08:51:33.122219181] msec_range[14] 0.100000 - 0.200000 : 74 [20081217-08:51:33.124293977] msec_range[15] 0.050000 - 0.100000 : 1270 [20081217-08:51:33.126478215] msec_range[16] 0.020000 - 0.050000 : 3382 [20081217-08:51:33.128523049] msec_range[17] 0.010000 - 0.020000 : 315 [20081217-08:51:33.130680277] msec_range[18] 0.000000 - 0.010000 : 77 [20081217-08:51:33.132800719] [20081217-08:51:33.135072159] [ read] 0.001000 5.907824 157.488998 6579200 [20081217-08:51:33.137236652] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-08:51:33.139401727] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-08:51:33.143852319] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-08:51:33.146733994] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-08:51:33.149196407] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-08:51:33.151566865] msec_range[5] 100.000000 - 200.000000 : 801 [20081217-08:51:33.153770136] msec_range[6] 50.000000 - 100.000000 : 1112 [20081217-08:51:33.156415698] msec_range[7] 20.000000 - 50.000000 : 52961 [20081217-08:51:33.159116503] msec_range[8] 10.000000 - 20.000000 : 675780 [20081217-08:51:33.161258617] msec_range[9] 5.000000 - 10.000000 : 2836962 [20081217-08:51:33.163277999] msec_range[10] 2.000000 - 5.000000 : 2491897 [20081217-08:51:33.165645303] msec_range[11] 1.000000 - 2.000000 : 92916 [20081217-08:51:33.167866388] msec_range[12] 0.500000 - 1.000000 : 44407 [20081217-08:51:33.170061903] msec_range[13] 0.200000 - 0.500000 : 4874 [20081217-08:51:33.172282354] msec_range[14] 0.100000 - 0.200000 : 632 [20081217-08:51:33.175012489] msec_range[15] 0.050000 - 0.100000 : 3711 [20081217-08:51:33.177708474] msec_range[16] 0.020000 - 0.050000 : 18314 [20081217-08:51:33.180308457] msec_range[17] 0.010000 - 0.020000 : 111501 [20081217-08:51:33.182644417] msec_range[18] 0.000000 - 0.010000 : 243332 [20081217-08:51:33.184927622] [20081217-08:51:33.187052267] [ lseek] 0.000000 0.001951 2.072000 6579200 [20081217-08:51:33.189227965] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-08:51:33.191364965] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-08:51:33.193693891] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-08:51:33.195895050] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-08:51:33.197981654] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-08:51:33.200698778] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-08:51:33.202897729] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-08:51:33.204993187] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-08:51:33.207101122] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-08:51:33.209256793] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-08:51:33.211555083] msec_range[10] 2.000000 - 5.000000 : 1 [20081217-08:51:33.214145230] msec_range[11] 1.000000 - 2.000000 : 15 [20081217-08:51:33.216848675] msec_range[12] 0.500000 - 1.000000 : 40 [20081217-08:51:33.219205007] msec_range[13] 0.200000 - 0.500000 : 370 [20081217-08:51:33.221261467] msec_range[14] 0.100000 - 0.200000 : 968 [20081217-08:51:33.223705499] msec_range[15] 0.050000 - 0.100000 : 1002 [20081217-08:51:33.225953587] msec_range[16] 0.020000 - 0.050000 : 8159 [20081217-08:51:33.227948380] msec_range[17] 0.010000 - 0.020000 : 17191 [20081217-08:51:33.229919692] msec_range[18] 0.000000 - 0.010000 : 6551454 [20081217-08:51:33.232159309] [20081217-08:51:33.234298047] [ close] 0.002000 0.008391 0.211000 5140 [20081217-08:51:33.236314754] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-08:51:33.238334593] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-08:51:33.241061626] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-08:51:33.243711186] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-08:51:33.246125869] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-08:51:33.248442128] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-08:51:33.250632294] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-08:51:33.252697224] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-08:51:33.254950765] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-08:51:33.257095166] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-08:51:33.259167303] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-08:51:33.261141341] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-08:51:33.263432587] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-08:51:33.265605183] msec_range[13] 0.200000 - 0.500000 : 1 [20081217-08:51:33.267742503] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-08:51:33.269836948] msec_range[15] 0.050000 - 0.100000 : 4 [20081217-08:51:33.272107353] msec_range[16] 0.020000 - 0.050000 : 61 [20081217-08:51:33.274343179] msec_range[17] 0.010000 - 0.020000 : 1109 [20081217-08:51:33.276391420] msec_range[18] 0.000000 - 0.010000 : 3965 [20081217-08:51:33.278329151] [20081217-08:51:33.280703038] [20081217-08:51:33.283620848] [20081217-08:51:33.286304882] [20081217-08:51:33.288795377] 8.4% User Time [20081217-08:51:33.291246416] 263.7% System Time [20081217-08:51:33.293481817] 272.1% CPU Utilization [20081217-08:51:33.295550186] Profilers reporting [20081217-08:52:03.822612076] Profilers postprocessing [20081217-08:52:04.958818454] Stopping profiling. [20081217-08:52:04.963450943] Killing daemon. [20081217-08:52:07.075636836] Processing File : /autobench/logs/ffsb.random_reads__threads_0128.08-12-17_08.46.10/analysis/oprofile.001 [20081217-08:52:07.077893302] Processing File : /autobench/logs/ffsb.random_reads__threads_0128.08-12-17_08.46.10/analysis/oprofile-brief.001 [20081217-08:52:07.261283997] Processing File : mpstat.001 [20081217-08:52:07.263394450] Discovered mpstat_interval=[5] [20081217-08:52:07.890306391] Processing Directory : sar.breakout.001 [20081217-08:52:07.892573353] Discovered sar_interval=[5] [20081217-08:52:08.129972062] Processing File : iostat.001 [20081217-08:52:08.132122179] Discovered iostat_interval=[5] [20081217-08:52:11.026819221] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0801/btrfs-baseline' [20081217-08:52:16.059610166] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-08:52:20.673094843] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-08:52:20.807934988] PROCESSING COMMAND : 'run random_writes__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb num_threads=1' [20081217-08:52:20.852498867] new log requested [20081217-08:52:20.876718998] Running command ffsb [20081217-08:52:30.393717487] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb [20081217-08:52:30.415047261] Importing argument : num_threads=1 [20081217-08:52:30.440635093] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-08:52:30.538468442] Checking for sar... [20081217-08:52:30.540693174] found [20081217-08:52:30.597190062] Checking for sar... [20081217-08:52:30.599420001] found [20081217-08:52:30.654937307] Checking for sar... [20081217-08:52:30.657181244] found [20081217-08:52:30.818530894] Checking for binutils-2.18 ... Already installed. [20081217-08:52:30.823028914] mv: cannot stat `lib64/*': No such file or directory [20081217-08:52:30.871814518] rmdir: lib64: No such file or directory [20081217-08:52:30.942454666] Checking for gettext-0.17 ... Already installed. [20081217-08:52:30.983408317] popt32-1.10.4 already installed. [20081217-08:52:30.998873227] popt64-1.10.4 already installed. [20081217-08:52:31.029766264] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-08:52:31.082659052] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-08:52:31.162934530] Daemon not running [20081217-08:52:31.183005371] Unloading oprofile module [20081217-08:52:31.397719410] Daemon not running [20081217-08:52:32.960536396] OPROFILE : using callgraph [5] [20081217-08:52:33.193655463] Daemon not running [20081217-08:52:33.195759033] Separate options: none [20081217-08:52:33.197770988] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-08:52:33.199929177] Image filter: none [20081217-08:52:33.201751568] Call-graph depth: 5 [20081217-08:52:33.282110824] FFSB version 6.0-RC2 started [20081217-08:52:33.284479498] [20081217-08:52:33.286401654] benchmark time = 300 [20081217-08:52:33.288692208] ThreadGroup 0 [20081217-08:52:33.290851883] ================ [20081217-08:52:33.293040034] num_threads = 1 [20081217-08:52:33.294809484] [20081217-08:52:33.296682432] read_random = off [20081217-08:52:33.298570799] read_size = 0 (0B) [20081217-08:52:33.300436577] read_blocksize = 0 (0B) [20081217-08:52:33.302173723] read_skip = off [20081217-08:52:33.304011797] read_skipsize = 0 (0B) [20081217-08:52:33.305821993] [20081217-08:52:33.307630592] write_random = on [20081217-08:52:33.309352036] write_size = 5242880 (5MB) [20081217-08:52:33.311157820] fsync_file = 0 [20081217-08:52:33.313049641] write_blocksize = 4096 (4KB) [20081217-08:52:33.314958692] wait time = 0 [20081217-08:52:33.316690969] [20081217-08:52:33.318539400] op weights [20081217-08:52:33.320328167] read = 0 (0.00%) [20081217-08:52:33.322228914] readall = 0 (0.00%) [20081217-08:52:33.323958763] write = 1 (100.00%) [20081217-08:52:33.325768876] create = 0 (0.00%) [20081217-08:52:33.327536635] append = 0 (0.00%) [20081217-08:52:33.329353004] delete = 0 (0.00%) [20081217-08:52:33.331082191] metaop = 0 (0.00%) [20081217-08:52:33.332886899] createdir = 0 (0.00%) [20081217-08:52:33.334673615] stat = 0 (0.00%) [20081217-08:52:33.336504072] writeall = 0 (0.00%) [20081217-08:52:33.338198236] writeall_fsync = 0 (0.00%) [20081217-08:52:33.340044606] open_close = 0 (0.00%) [20081217-08:52:33.341954402] write_fsync = 0 (0.00%) [20081217-08:52:33.343818833] create_fsync = 0 (0.00%) [20081217-08:52:33.345536518] append_fsync = 0 (0.00%) [20081217-08:52:33.347358307] [20081217-08:52:33.349450830] FileSystem /mnt/ffsb1 [20081217-08:52:33.351563585] ========== [20081217-08:52:33.353684400] num_dirs = 0 [20081217-08:52:33.355678454] starting files = 1024 [20081217-08:52:33.357671937] [20081217-08:52:33.359412386] min file size = 104857600 (100MB) [20081217-08:52:33.361241596] max file size = 104857600 (100MB) [20081217-08:52:33.363040983] directio = off [20081217-08:52:33.364894391] alignedio = on [20081217-08:52:33.366659517] bufferedio = off [20081217-08:52:33.368540584] [20081217-08:52:33.370594247] aging is off [20081217-08:52:33.372491865] current utilization = 4.47% [20081217-08:52:33.374196502] [20081217-08:52:33.376054944] checking existing fs: /mnt/ffsb1 [20081217-08:52:33.626550385] fs setup took 0 secs [20081217-08:52:34.549871462] Syncing()...0 sec [20081217-08:52:34.551818328] Starting Actual Benchmark At: Wed Dec 17 08:52:34 2008 [20081217-08:52:34.565277368] [20081217-08:57:53.057689934] Syncing()...5 sec [20081217-08:57:53.067239385] FFSB benchmark finished at: Wed Dec 17 08:57:53 2008 [20081217-08:57:53.070231399] [20081217-08:57:53.073122363] Results: [20081217-08:57:53.090136576] Benchmark took 318.51 sec [20081217-08:57:53.093814038] [20081217-08:57:53.096270837] Total Results [20081217-08:57:53.111885280] =============== [20081217-08:57:53.115341100] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-08:57:53.118056236] ======= ============ ========= ======= =========== ========== [20081217-08:57:53.120560111] write : 1021440 3206.96 100.000% 100.000% 251MB/sec [20081217-08:57:53.123055720] - [20081217-08:57:53.125354580] 3206.96 Transactions per Second [20081217-08:57:53.127838936] [20081217-08:57:53.130804272] Throughput Results [20081217-08:57:53.144472627] =================== [20081217-08:57:53.146898944] Write Throughput: 251MB/sec [20081217-08:57:53.150878891] [20081217-08:57:53.152884155] System Call Latency statistics in millisecs [20081217-08:57:53.155696694] ===== [20081217-08:57:53.158401501] Min Avg Max Total Calls [20081217-08:57:53.161818119] ======== ======== ======== ============ [20081217-08:57:53.166460274] [ open] 0.015000 0.034159 3.666000 798 [20081217-08:57:53.169862812] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-08:57:53.172611441] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-08:57:53.175182937] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-08:57:53.178319454] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-08:57:53.181469564] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-08:57:53.185599569] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-08:57:53.188531229] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-08:57:53.191277009] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-08:57:53.194419289] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-08:57:53.197405594] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-08:57:53.199910601] msec_range[10] 2.000000 - 5.000000 : 1 [20081217-08:57:53.202751412] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-08:57:53.206506258] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-08:57:53.209155699] msec_range[13] 0.200000 - 0.500000 : 5 [20081217-08:57:53.211858818] msec_range[14] 0.100000 - 0.200000 : 6 [20081217-08:57:53.214714036] msec_range[15] 0.050000 - 0.100000 : 21 [20081217-08:57:53.217815912] msec_range[16] 0.020000 - 0.050000 : 701 [20081217-08:57:53.220726486] msec_range[17] 0.010000 - 0.020000 : 64 [20081217-08:57:53.224170460] msec_range[18] 0.000000 - 0.010000 : 0 [20081217-08:57:53.227230137] [20081217-08:57:53.230280827] [ write] 0.009000 0.303070 17836.544922 1021440 [20081217-08:57:53.232988713] msec_range[0] 5000.000000 - 10000.000000 : 9 [20081217-08:57:53.235611575] msec_range[1] 2000.000000 - 5000.000000 : 2 [20081217-08:57:53.238440897] msec_range[2] 1000.000000 - 2000.000000 : 4 [20081217-08:57:53.241106925] msec_range[3] 500.000000 - 1000.000000 : 3 [20081217-08:57:53.245314691] msec_range[4] 200.000000 - 500.000000 : 13 [20081217-08:57:53.247949841] msec_range[5] 100.000000 - 200.000000 : 39 [20081217-08:57:53.250480663] msec_range[6] 50.000000 - 100.000000 : 128 [20081217-08:57:53.253313644] msec_range[7] 20.000000 - 50.000000 : 101 [20081217-08:57:53.256213999] msec_range[8] 10.000000 - 20.000000 : 179 [20081217-08:57:53.260810359] msec_range[9] 5.000000 - 10.000000 : 281 [20081217-08:57:53.263558657] msec_range[10] 2.000000 - 5.000000 : 1081 [20081217-08:57:53.266150472] msec_range[11] 1.000000 - 2.000000 : 3479 [20081217-08:57:53.269092186] msec_range[12] 0.500000 - 1.000000 : 6852 [20081217-08:57:53.271666834] msec_range[13] 0.200000 - 0.500000 : 28018 [20081217-08:57:53.274254972] msec_range[14] 0.100000 - 0.200000 : 84146 [20081217-08:57:53.277058398] msec_range[15] 0.050000 - 0.100000 : 374206 [20081217-08:57:53.280348607] msec_range[16] 0.020000 - 0.050000 : 349576 [20081217-08:57:53.282862564] msec_range[17] 0.010000 - 0.020000 : 173295 [20081217-08:57:53.285641454] msec_range[18] 0.000000 - 0.010000 : 19 [20081217-08:57:53.288061326] [20081217-08:57:53.290907099] [ lseek] 0.000000 0.001433 5.754000 1021440 [20081217-08:57:53.293542850] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-08:57:53.296380170] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-08:57:53.298758438] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-08:57:53.301267507] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-08:57:53.304925558] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-08:57:53.307702755] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-08:57:53.310116345] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-08:57:53.312771613] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-08:57:53.315450726] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-08:57:53.319237647] msec_range[9] 5.000000 - 10.000000 : 1 [20081217-08:57:53.322279131] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-08:57:53.324836038] msec_range[11] 1.000000 - 2.000000 : 10 [20081217-08:57:53.327470744] msec_range[12] 0.500000 - 1.000000 : 10 [20081217-08:57:53.330012653] msec_range[13] 0.200000 - 0.500000 : 2 [20081217-08:57:53.332716728] msec_range[14] 0.100000 - 0.200000 : 1 [20081217-08:57:53.337483094] msec_range[15] 0.050000 - 0.100000 : 18 [20081217-08:57:53.340044851] msec_range[16] 0.020000 - 0.050000 : 115 [20081217-08:57:53.342770810] msec_range[17] 0.010000 - 0.020000 : 1422 [20081217-08:57:53.345527793] msec_range[18] 0.000000 - 0.010000 : 1019861 [20081217-08:57:53.348694442] [20081217-08:57:53.351755108] [ close] 0.003000 0.007165 0.044000 798 [20081217-08:57:53.354137600] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-08:57:53.356609526] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-08:57:53.359021934] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-08:57:53.361450484] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-08:57:53.363723868] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-08:57:53.366229884] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-08:57:53.368511238] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-08:57:53.370595141] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-08:57:53.372901615] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-08:57:53.375138391] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-08:57:53.377235828] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-08:57:53.379556436] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-08:57:53.381812762] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-08:57:53.384128855] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-08:57:53.386307995] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-08:57:53.388480297] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-08:57:53.390774809] msec_range[16] 0.020000 - 0.050000 : 2 [20081217-08:57:53.393016791] msec_range[17] 0.010000 - 0.020000 : 89 [20081217-08:57:53.395320887] msec_range[18] 0.000000 - 0.010000 : 707 [20081217-08:57:53.397470371] [20081217-08:57:53.399727067] [20081217-08:57:53.402001185] [20081217-08:57:53.404183668] [20081217-08:57:53.407777590] 1.1% User Time [20081217-08:57:53.410016824] 23.1% System Time [20081217-08:57:53.412140026] 24.2% CPU Utilization [20081217-08:57:53.414388440] Profilers reporting [20081217-08:58:10.833942441] Profilers postprocessing [20081217-08:58:11.971797136] Stopping profiling. [20081217-08:58:11.976191477] Killing daemon. [20081217-08:58:13.336919851] Processing File : /autobench/logs/ffsb.random_writes__threads_0001.08-12-17_08.52.20/analysis/oprofile.001 [20081217-08:58:13.339282191] Processing File : /autobench/logs/ffsb.random_writes__threads_0001.08-12-17_08.52.20/analysis/oprofile-brief.001 [20081217-08:58:13.475551953] Processing File : mpstat.001 [20081217-08:58:13.477601816] Discovered mpstat_interval=[5] [20081217-08:58:14.058556542] Processing Directory : sar.breakout.001 [20081217-08:58:14.060830139] Discovered sar_interval=[5] [20081217-08:58:14.230728210] Processing File : iostat.001 [20081217-08:58:14.233115316] Discovered iostat_interval=[5] [20081217-08:58:15.933368786] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0801/btrfs-baseline' [20081217-08:58:19.512145301] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-08:58:22.940867098] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-08:58:23.442706831] PROCESSING COMMAND : 'run random_writes__threads_0016 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb num_threads=16' [20081217-08:58:23.486448654] new log requested [20081217-08:58:23.510722542] Running command ffsb [20081217-08:58:32.201634426] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb [20081217-08:58:32.217231441] Importing argument : num_threads=16 [20081217-08:58:32.242988970] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-08:58:32.331379044] Checking for sar... [20081217-08:58:32.333539585] found [20081217-08:58:32.389461006] Checking for sar... [20081217-08:58:32.391568244] found [20081217-08:58:32.447298392] Checking for sar... [20081217-08:58:32.449538817] found [20081217-08:58:32.593367335] Checking for binutils-2.18 ... Already installed. [20081217-08:58:32.611141547] mv: cannot stat `lib64/*': No such file or directory [20081217-08:58:32.618980234] rmdir: lib64: No such file or directory [20081217-08:58:32.684733238] Checking for gettext-0.17 ... Already installed. [20081217-08:58:32.726057939] popt32-1.10.4 already installed. [20081217-08:58:32.741070297] popt64-1.10.4 already installed. [20081217-08:58:32.772086538] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-08:58:32.824642391] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-08:58:32.905906483] Daemon not running [20081217-08:58:32.922464413] Unloading oprofile module [20081217-08:58:33.137462040] Daemon not running [20081217-08:58:34.208123897] OPROFILE : using callgraph [5] [20081217-08:58:34.439240208] Daemon not running [20081217-08:58:34.441299011] Separate options: none [20081217-08:58:34.443466313] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-08:58:34.445555657] Image filter: none [20081217-08:58:34.447556968] Call-graph depth: 5 [20081217-08:58:34.506065431] FFSB version 6.0-RC2 started [20081217-08:58:34.508058710] [20081217-08:58:34.567542777] benchmark time = 300 [20081217-08:58:34.569508640] ThreadGroup 0 [20081217-08:58:34.571258868] ================ [20081217-08:58:34.573359173] num_threads = 16 [20081217-08:58:34.575486319] [20081217-08:58:34.577565046] read_random = off [20081217-08:58:34.579313321] read_size = 0 (0B) [20081217-08:58:34.581178348] read_blocksize = 0 (0B) [20081217-08:58:34.583092793] read_skip = off [20081217-08:58:34.585003222] read_skipsize = 0 (0B) [20081217-08:58:34.586718080] [20081217-08:58:34.588537974] write_random = on [20081217-08:58:34.590717516] write_size = 5242880 (5MB) [20081217-08:58:34.592757530] fsync_file = 0 [20081217-08:58:34.594797004] write_blocksize = 4096 (4KB) [20081217-08:58:34.596656240] wait time = 0 [20081217-08:58:34.598639951] [20081217-08:58:34.600404842] op weights [20081217-08:58:34.602256199] read = 0 (0.00%) [20081217-08:58:34.604077541] readall = 0 (0.00%) [20081217-08:58:34.605899100] write = 1 (100.00%) [20081217-08:58:34.607649777] create = 0 (0.00%) [20081217-08:58:34.609546619] append = 0 (0.00%) [20081217-08:58:34.611513775] delete = 0 (0.00%) [20081217-08:58:34.613501947] metaop = 0 (0.00%) [20081217-08:58:34.615244791] createdir = 0 (0.00%) [20081217-08:58:34.617159681] stat = 0 (0.00%) [20081217-08:58:34.618972707] writeall = 0 (0.00%) [20081217-08:58:34.620799870] writeall_fsync = 0 (0.00%) [20081217-08:58:34.622509662] open_close = 0 (0.00%) [20081217-08:58:34.624408725] write_fsync = 0 (0.00%) [20081217-08:58:34.626298874] create_fsync = 0 (0.00%) [20081217-08:58:34.628166159] append_fsync = 0 (0.00%) [20081217-08:58:34.629910390] [20081217-08:58:34.631720398] FileSystem /mnt/ffsb1 [20081217-08:58:34.633521986] ========== [20081217-08:58:34.635372649] num_dirs = 0 [20081217-08:58:34.637085808] starting files = 1024 [20081217-08:58:34.638887923] [20081217-08:58:34.640639388] min file size = 104857600 (100MB) [20081217-08:58:34.642473664] max file size = 104857600 (100MB) [20081217-08:58:34.644243732] directio = off [20081217-08:58:34.646064896] alignedio = on [20081217-08:58:34.647884472] bufferedio = off [20081217-08:58:34.649745776] [20081217-08:58:34.651464541] aging is off [20081217-08:58:34.653268665] current utilization = 4.65% [20081217-08:58:34.655011368] [20081217-08:58:34.656809074] checking existing fs: /mnt/ffsb1 [20081217-08:58:35.863728201] fs setup took 1 secs [20081217-08:58:36.791015426] Syncing()...0 sec [20081217-08:58:36.793123275] Starting Actual Benchmark At: Wed Dec 17 08:58:36 2008 [20081217-08:58:36.806297616] [20081217-09:04:10.847783301] Syncing()...23 sec [20081217-09:04:10.859332822] FFSB benchmark finished at: Wed Dec 17 09:04:10 2008 [20081217-09:04:10.861341035] [20081217-09:04:10.863802300] Results: [20081217-09:04:10.881450137] Benchmark took 334.06 sec [20081217-09:04:10.883400126] [20081217-09:04:10.885822192] Total Results [20081217-09:04:10.899624391] =============== [20081217-09:04:10.902380174] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-09:04:10.904642972] ======= ============ ========= ======= =========== ========== [20081217-09:04:10.907758533] write : 677120 2026.96 100.000% 100.000% 158MB/sec [20081217-09:04:10.910248023] - [20081217-09:04:10.912780090] 2026.96 Transactions per Second [20081217-09:04:10.915730354] [20081217-09:04:10.918060260] Throughput Results [20081217-09:04:10.934130704] =================== [20081217-09:04:10.936577540] Write Throughput: 158MB/sec [20081217-09:04:10.939127135] [20081217-09:04:10.941461456] System Call Latency statistics in millisecs [20081217-09:04:10.960154450] ===== [20081217-09:04:10.962752431] Min Avg Max Total Calls [20081217-09:04:10.965423001] ======== ======== ======== ============ [20081217-09:04:10.967995282] [ open] 0.009000 0.031272 0.292000 529 [20081217-09:04:10.970804703] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:04:10.973309623] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:04:10.975752639] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:04:10.979983377] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-09:04:10.983566563] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-09:04:10.986102382] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-09:04:10.988466260] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-09:04:10.991162317] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-09:04:10.994310377] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-09:04:10.996845519] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-09:04:10.999439419] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-09:04:11.001975714] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-09:04:11.004730450] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-09:04:11.007177588] msec_range[13] 0.200000 - 0.500000 : 1 [20081217-09:04:11.009747742] msec_range[14] 0.100000 - 0.200000 : 1 [20081217-09:04:11.012416642] msec_range[15] 0.050000 - 0.100000 : 18 [20081217-09:04:11.015676397] msec_range[16] 0.020000 - 0.050000 : 468 [20081217-09:04:11.018405550] msec_range[17] 0.010000 - 0.020000 : 37 [20081217-09:04:11.020686269] msec_range[18] 0.000000 - 0.010000 : 4 [20081217-09:04:11.022973058] [20081217-09:04:11.025402136] [ write] 0.010000 7.125774 34205.656250 677120 [20081217-09:04:11.027541728] msec_range[0] 5000.000000 - 10000.000000 : 56 [20081217-09:04:11.029795353] msec_range[1] 2000.000000 - 5000.000000 : 78 [20081217-09:04:11.031793214] msec_range[2] 1000.000000 - 2000.000000 : 97 [20081217-09:04:11.033951271] msec_range[3] 500.000000 - 1000.000000 : 109 [20081217-09:04:11.037149221] msec_range[4] 200.000000 - 500.000000 : 151 [20081217-09:04:11.041072139] msec_range[5] 100.000000 - 200.000000 : 106 [20081217-09:04:11.043962647] msec_range[6] 50.000000 - 100.000000 : 290 [20081217-09:04:11.046494116] msec_range[7] 20.000000 - 50.000000 : 1972 [20081217-09:04:11.048760235] msec_range[8] 10.000000 - 20.000000 : 13824 [20081217-09:04:11.051241181] msec_range[9] 5.000000 - 10.000000 : 90892 [20081217-09:04:11.056452422] msec_range[10] 2.000000 - 5.000000 : 221110 [20081217-09:04:11.058821890] msec_range[11] 1.000000 - 2.000000 : 79001 [20081217-09:04:11.061000772] msec_range[12] 0.500000 - 1.000000 : 58923 [20081217-09:04:11.063539444] msec_range[13] 0.200000 - 0.500000 : 70358 [20081217-09:04:11.066361537] msec_range[14] 0.100000 - 0.200000 : 31984 [20081217-09:04:11.068610470] msec_range[15] 0.050000 - 0.100000 : 51451 [20081217-09:04:11.070736858] msec_range[16] 0.020000 - 0.050000 : 41949 [20081217-09:04:11.073255494] msec_range[17] 0.010000 - 0.020000 : 14634 [20081217-09:04:11.076087582] msec_range[18] 0.000000 - 0.010000 : 0 [20081217-09:04:11.081152089] [20081217-09:04:11.084134772] [ lseek] 0.000000 0.108131 18764.484375 677120 [20081217-09:04:11.086639869] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:04:11.089301121] msec_range[1] 2000.000000 - 5000.000000 : 3 [20081217-09:04:11.093999848] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:04:11.100073290] msec_range[3] 500.000000 - 1000.000000 : 1 [20081217-09:04:11.103199285] msec_range[4] 200.000000 - 500.000000 : 1 [20081217-09:04:11.105623885] msec_range[5] 100.000000 - 200.000000 : 1 [20081217-09:04:11.108294532] msec_range[6] 50.000000 - 100.000000 : 4 [20081217-09:04:11.112023113] msec_range[7] 20.000000 - 50.000000 : 33 [20081217-09:04:11.115263902] msec_range[8] 10.000000 - 20.000000 : 35 [20081217-09:04:11.117814873] msec_range[9] 5.000000 - 10.000000 : 227 [20081217-09:04:11.120180276] msec_range[10] 2.000000 - 5.000000 : 439 [20081217-09:04:11.122359293] msec_range[11] 1.000000 - 2.000000 : 450 [20081217-09:04:11.125328904] msec_range[12] 0.500000 - 1.000000 : 76 [20081217-09:04:11.127893317] msec_range[13] 0.200000 - 0.500000 : 157 [20081217-09:04:11.130443472] msec_range[14] 0.100000 - 0.200000 : 116 [20081217-09:04:11.133014513] msec_range[15] 0.050000 - 0.100000 : 261 [20081217-09:04:11.135452260] msec_range[16] 0.020000 - 0.050000 : 646 [20081217-09:04:11.137843682] msec_range[17] 0.010000 - 0.020000 : 3730 [20081217-09:04:11.139832798] msec_range[18] 0.000000 - 0.010000 : 670937 [20081217-09:04:11.142313044] [20081217-09:04:11.144481150] [ close] 0.003000 0.009355 0.129000 529 [20081217-09:04:11.146350615] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:04:11.148519157] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:04:11.150504374] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:04:11.152361534] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-09:04:11.160105577] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-09:04:11.162584012] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-09:04:11.164827004] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-09:04:11.166784910] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-09:04:11.169222183] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-09:04:11.171966903] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-09:04:11.173802702] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-09:04:11.176093271] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-09:04:11.178224778] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-09:04:11.180153568] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-09:04:11.182451955] msec_range[14] 0.100000 - 0.200000 : 1 [20081217-09:04:11.184591451] msec_range[15] 0.050000 - 0.100000 : 2 [20081217-09:04:11.186720588] msec_range[16] 0.020000 - 0.050000 : 10 [20081217-09:04:11.189015142] msec_range[17] 0.010000 - 0.020000 : 131 [20081217-09:04:11.191529259] msec_range[18] 0.000000 - 0.010000 : 385 [20081217-09:04:11.193683440] [20081217-09:04:11.195513846] [20081217-09:04:11.199279583] [20081217-09:04:11.201293075] [20081217-09:04:11.203201161] 0.7% User Time [20081217-09:04:11.205226195] 126.2% System Time [20081217-09:04:11.207571508] 127.0% CPU Utilization [20081217-09:04:11.209660693] Profilers reporting [20081217-09:04:27.602919902] Profilers postprocessing [20081217-09:04:28.767457249] Stopping profiling. [20081217-09:04:28.772788109] Killing daemon. [20081217-09:04:31.125348484] Processing File : /autobench/logs/ffsb.random_writes__threads_0016.08-12-17_08.58.23/analysis/oprofile.001 [20081217-09:04:31.127526882] Processing File : /autobench/logs/ffsb.random_writes__threads_0016.08-12-17_08.58.23/analysis/oprofile-brief.001 [20081217-09:04:31.281623748] Processing File : mpstat.001 [20081217-09:04:31.283807719] Discovered mpstat_interval=[5] [20081217-09:04:31.886690538] Processing Directory : sar.breakout.001 [20081217-09:04:31.888941826] Discovered sar_interval=[5] [20081217-09:04:32.032020133] Processing File : iostat.001 [20081217-09:04:32.034228290] Discovered iostat_interval=[5] [20081217-09:04:38.939262216] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0801/btrfs-baseline' [20081217-09:04:42.517585372] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-09:04:46.429272578] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-09:04:46.695818961] PROCESSING COMMAND : 'run random_writes__threads_0128 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb num_threads=128' [20081217-09:04:46.740483132] new log requested [20081217-09:04:46.764688973] Running command ffsb [20081217-09:04:55.728705528] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb [20081217-09:04:55.744305136] Importing argument : num_threads=128 [20081217-09:04:55.770417540] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-09:04:55.859275839] Checking for sar... [20081217-09:04:55.861597523] found [20081217-09:04:55.918139476] Checking for sar... [20081217-09:04:55.920327279] found [20081217-09:04:55.976253840] Checking for sar... [20081217-09:04:55.978623725] found [20081217-09:04:56.120154286] Checking for binutils-2.18 ... Already installed. [20081217-09:04:56.133905853] mv: cannot stat `lib64/*': No such file or directory [20081217-09:04:56.139984960] rmdir: lib64: No such file or directory [20081217-09:04:56.206224632] Checking for gettext-0.17 ... Already installed. [20081217-09:04:56.247950609] popt32-1.10.4 already installed. [20081217-09:04:56.263607024] popt64-1.10.4 already installed. [20081217-09:04:56.294215050] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-09:04:56.346873714] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-09:04:56.427340407] Daemon not running [20081217-09:04:56.443260801] Unloading oprofile module [20081217-09:04:56.622023776] Daemon not running [20081217-09:04:57.618799569] OPROFILE : using callgraph [5] [20081217-09:04:57.852214368] Daemon not running [20081217-09:04:57.854217978] Separate options: none [20081217-09:04:57.856438592] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-09:04:57.858527198] Image filter: none [20081217-09:04:57.860578754] Call-graph depth: 5 [20081217-09:04:57.919288556] FFSB version 6.0-RC2 started [20081217-09:04:57.921311506] [20081217-09:04:58.413413739] benchmark time = 300 [20081217-09:04:58.415403998] ThreadGroup 0 [20081217-09:04:58.417192896] ================ [20081217-09:04:58.419304323] num_threads = 128 [20081217-09:04:58.421432353] [20081217-09:04:58.423518778] read_random = off [20081217-09:04:58.425369130] read_size = 0 (0B) [20081217-09:04:58.427233388] read_blocksize = 0 (0B) [20081217-09:04:58.429064189] read_skip = off [20081217-09:04:58.431037397] read_skipsize = 0 (0B) [20081217-09:04:58.432836844] [20081217-09:04:58.434749069] write_random = on [20081217-09:04:58.436593270] write_size = 5242880 (5MB) [20081217-09:04:58.438518164] fsync_file = 0 [20081217-09:04:58.440321781] write_blocksize = 4096 (4KB) [20081217-09:04:58.442142802] wait time = 0 [20081217-09:04:58.443898885] [20081217-09:04:58.445735991] op weights [20081217-09:04:58.447512656] read = 0 (0.00%) [20081217-09:04:58.449376860] readall = 0 (0.00%) [20081217-09:04:58.451225210] write = 1 (100.00%) [20081217-09:04:58.453201803] create = 0 (0.00%) [20081217-09:04:58.455082493] append = 0 (0.00%) [20081217-09:04:58.456927786] delete = 0 (0.00%) [20081217-09:04:58.458668860] metaop = 0 (0.00%) [20081217-09:04:58.460554281] createdir = 0 (0.00%) [20081217-09:04:58.462348330] stat = 0 (0.00%) [20081217-09:04:58.464177765] writeall = 0 (0.00%) [20081217-09:04:58.466530086] writeall_fsync = 0 (0.00%) [20081217-09:04:58.468566714] open_close = 0 (0.00%) [20081217-09:04:58.470385993] write_fsync = 0 (0.00%) [20081217-09:04:58.472199479] create_fsync = 0 (0.00%) [20081217-09:04:58.473973928] append_fsync = 0 (0.00%) [20081217-09:04:58.475821726] [20081217-09:04:58.477600472] FileSystem /mnt/ffsb1 [20081217-09:04:58.479417303] ========== [20081217-09:04:58.481276120] num_dirs = 0 [20081217-09:04:58.483245011] starting files = 1024 [20081217-09:04:58.485160654] [20081217-09:04:58.486982401] min file size = 104857600 (100MB) [20081217-09:04:58.488894826] max file size = 104857600 (100MB) [20081217-09:04:58.490904083] directio = off [20081217-09:04:58.492662688] alignedio = on [20081217-09:04:58.494474659] bufferedio = off [20081217-09:04:58.496233747] [20081217-09:04:58.498137592] aging is off [20081217-09:04:58.499909038] current utilization = 4.76% [20081217-09:04:58.501718275] [20081217-09:04:58.503502107] checking existing fs: /mnt/ffsb1 [20081217-09:05:02.006942536] fs setup took 3 secs [20081217-09:05:02.441112074] Syncing()...0 sec [20081217-09:05:02.446633050] Starting Actual Benchmark At: Wed Dec 17 09:05:02 2008 [20081217-09:05:02.460157831] [20081217-09:12:52.474270237] Syncing()...93 sec [20081217-09:12:52.487284305] FFSB benchmark finished at: Wed Dec 17 09:12:52 2008 [20081217-09:12:52.489930672] [20081217-09:12:52.492627374] Results: [20081217-09:12:52.510028805] Benchmark took 470.03 sec [20081217-09:12:52.512582882] [20081217-09:12:52.516021187] Total Results [20081217-09:12:52.530323621] =============== [20081217-09:12:52.533651045] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-09:12:52.536099745] ======= ============ ========= ======= =========== ========== [20081217-09:12:52.538552004] write : 455680 969.46 100.000% 100.000% 75.7MB/sec [20081217-09:12:52.540891922] - [20081217-09:12:52.542960177] 969.46 Transactions per Second [20081217-09:12:52.545079347] [20081217-09:12:52.547599249] Throughput Results [20081217-09:12:52.562672940] =================== [20081217-09:12:52.567049217] Write Throughput: 75.7MB/sec [20081217-09:12:52.570467381] [20081217-09:12:52.572905206] System Call Latency statistics in millisecs [20081217-09:12:52.576485809] ===== [20081217-09:12:52.580371515] Min Avg Max Total Calls [20081217-09:12:52.583329047] ======== ======== ======== ============ [20081217-09:12:52.585995605] [ open] 0.005000 0.032994 0.838000 356 [20081217-09:12:52.589333057] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:12:52.592126051] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:12:52.595036837] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:12:52.597970708] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-09:12:52.600549692] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-09:12:52.603033506] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-09:12:52.605650137] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-09:12:52.608044842] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-09:12:52.610558212] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-09:12:52.613176093] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-09:12:52.615892187] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-09:12:52.618546961] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-09:12:52.622012626] msec_range[12] 0.500000 - 1.000000 : 2 [20081217-09:12:52.624737326] msec_range[13] 0.200000 - 0.500000 : 3 [20081217-09:12:52.627486801] msec_range[14] 0.100000 - 0.200000 : 4 [20081217-09:12:52.630011663] msec_range[15] 0.050000 - 0.100000 : 11 [20081217-09:12:52.633063172] msec_range[16] 0.020000 - 0.050000 : 201 [20081217-09:12:52.635831877] msec_range[17] 0.010000 - 0.020000 : 63 [20081217-09:12:52.638619711] msec_range[18] 0.000000 - 0.010000 : 72 [20081217-09:12:52.641096292] [20081217-09:12:52.643760905] [ write] 0.010000 98.234186 53562.062500 455680 [20081217-09:12:52.647791584] msec_range[0] 5000.000000 - 10000.000000 : 90 [20081217-09:12:52.650326908] msec_range[1] 2000.000000 - 5000.000000 : 557 [20081217-09:12:52.653574444] msec_range[2] 1000.000000 - 2000.000000 : 822 [20081217-09:12:52.656762496] msec_range[3] 500.000000 - 1000.000000 : 567 [20081217-09:12:52.659332748] msec_range[4] 200.000000 - 500.000000 : 1235 [20081217-09:12:52.661871315] msec_range[5] 100.000000 - 200.000000 : 2651 [20081217-09:12:52.664375036] msec_range[6] 50.000000 - 100.000000 : 9255 [20081217-09:12:52.666493786] msec_range[7] 20.000000 - 50.000000 : 179310 [20081217-09:12:52.668684756] msec_range[8] 10.000000 - 20.000000 : 132886 [20081217-09:12:52.671238738] msec_range[9] 5.000000 - 10.000000 : 47063 [20081217-09:12:52.674092817] msec_range[10] 2.000000 - 5.000000 : 12493 [20081217-09:12:52.678301687] msec_range[11] 1.000000 - 2.000000 : 2487 [20081217-09:12:52.680751643] msec_range[12] 0.500000 - 1.000000 : 2024 [20081217-09:12:52.685670162] msec_range[13] 0.200000 - 0.500000 : 10492 [20081217-09:12:52.688451531] msec_range[14] 0.100000 - 0.200000 : 11250 [20081217-09:12:52.691354305] msec_range[15] 0.050000 - 0.100000 : 10070 [20081217-09:12:52.694188926] msec_range[16] 0.020000 - 0.050000 : 23027 [20081217-09:12:52.696811249] msec_range[17] 0.010000 - 0.020000 : 8407 [20081217-09:12:52.700163419] msec_range[18] 0.000000 - 0.010000 : 0 [20081217-09:12:52.703586874] [20081217-09:12:52.706437292] [ lseek] 0.000000 1.775935 51795.304688 455680 [20081217-09:12:52.709252348] msec_range[0] 5000.000000 - 10000.000000 : 3 [20081217-09:12:52.711712940] msec_range[1] 2000.000000 - 5000.000000 : 2 [20081217-09:12:52.715144386] msec_range[2] 1000.000000 - 2000.000000 : 1 [20081217-09:12:52.718960522] msec_range[3] 500.000000 - 1000.000000 : 1 [20081217-09:12:52.721960574] msec_range[4] 200.000000 - 500.000000 : 42 [20081217-09:12:52.724327883] msec_range[5] 100.000000 - 200.000000 : 141 [20081217-09:12:52.727028620] msec_range[6] 50.000000 - 100.000000 : 343 [20081217-09:12:52.729435487] msec_range[7] 20.000000 - 50.000000 : 956 [20081217-09:12:52.731969759] msec_range[8] 10.000000 - 20.000000 : 1034 [20081217-09:12:52.734848573] msec_range[9] 5.000000 - 10.000000 : 643 [20081217-09:12:52.737610306] msec_range[10] 2.000000 - 5.000000 : 525 [20081217-09:12:52.740153833] msec_range[11] 1.000000 - 2.000000 : 602 [20081217-09:12:52.742792101] msec_range[12] 0.500000 - 1.000000 : 488 [20081217-09:12:52.745479997] msec_range[13] 0.200000 - 0.500000 : 243 [20081217-09:12:52.747951904] msec_range[14] 0.100000 - 0.200000 : 208 [20081217-09:12:52.750564255] msec_range[15] 0.050000 - 0.100000 : 164 [20081217-09:12:52.752982652] msec_range[16] 0.020000 - 0.050000 : 759 [20081217-09:12:52.755468553] msec_range[17] 0.010000 - 0.020000 : 4525 [20081217-09:12:52.758430049] msec_range[18] 0.000000 - 0.010000 : 444978 [20081217-09:12:52.760556881] [20081217-09:12:52.763002440] [ close] 0.003000 0.010121 0.322000 356 [20081217-09:12:52.765611478] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:12:52.768208564] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:12:52.770481951] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:12:52.772844800] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-09:12:52.775182899] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-09:12:52.777402602] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-09:12:52.779528006] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-09:12:52.781603825] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-09:12:52.784062782] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-09:12:52.789403040] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-09:12:52.791367193] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-09:12:52.793667129] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-09:12:52.795739851] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-09:12:52.797714651] msec_range[13] 0.200000 - 0.500000 : 1 [20081217-09:12:52.799987501] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-09:12:52.802013937] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-09:12:52.803982152] msec_range[16] 0.020000 - 0.050000 : 8 [20081217-09:12:52.806196922] msec_range[17] 0.010000 - 0.020000 : 106 [20081217-09:12:52.808226530] msec_range[18] 0.000000 - 0.010000 : 241 [20081217-09:12:52.810177242] [20081217-09:12:52.812405334] [20081217-09:12:52.814443911] [20081217-09:12:52.816400402] [20081217-09:12:52.818626306] 0.2% User Time [20081217-09:12:52.821801523] 210.5% System Time [20081217-09:12:52.823774770] 210.7% CPU Utilization [20081217-09:12:52.826006796] Profilers reporting [20081217-09:13:12.431157679] Profilers postprocessing [20081217-09:13:13.567018577] Stopping profiling. [20081217-09:13:13.571908349] Killing daemon. [20081217-09:13:14.763698944] Processing File : /autobench/logs/ffsb.random_writes__threads_0128.08-12-17_09.04.46/analysis/oprofile.001 [20081217-09:13:14.766046976] Processing File : /autobench/logs/ffsb.random_writes__threads_0128.08-12-17_09.04.46/analysis/oprofile-brief.001 [20081217-09:13:14.921708884] Processing File : mpstat.001 [20081217-09:13:14.923812681] Discovered mpstat_interval=[5] [20081217-09:13:15.618622858] Processing Directory : sar.breakout.001 [20081217-09:13:15.620873199] Discovered sar_interval=[5] [20081217-09:13:15.808239502] Processing File : iostat.001 [20081217-09:13:15.810649458] Discovered iostat_interval=[5] [20081217-09:13:17.649440408] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0801/btrfs-baseline' [20081217-09:13:21.623183235] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-09:13:25.724913603] PROCESSING COMMAND : 'mount -t btrfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-09:13:25.973885794] PROCESSING COMMAND : 'run random_writes_odirect__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb num_threads=1' [20081217-09:13:26.018419055] new log requested [20081217-09:13:26.042515741] Running command ffsb [20081217-09:13:34.850993462] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb [20081217-09:13:34.866822224] Importing argument : num_threads=1 [20081217-09:13:34.893269181] Found a btrfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-09:13:34.981525166] Checking for sar... [20081217-09:13:34.983634201] found [20081217-09:13:35.040510096] Checking for sar... [20081217-09:13:35.042656025] found [20081217-09:13:35.098901573] Checking for sar... [20081217-09:13:35.101188649] found [20081217-09:13:35.242495892] Checking for binutils-2.18 ... Already installed. [20081217-09:13:35.256321947] mv: cannot stat `lib64/*': No such file or directory [20081217-09:13:35.262214668] rmdir: lib64: No such file or directory [20081217-09:13:35.328085160] Checking for gettext-0.17 ... Already installed. [20081217-09:13:35.369308172] popt32-1.10.4 already installed. [20081217-09:13:35.384411465] popt64-1.10.4 already installed. [20081217-09:13:35.415064341] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-09:13:35.468043732] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-09:13:35.548511779] Daemon not running [20081217-09:13:35.565426400] Unloading oprofile module [20081217-09:13:35.739429331] Daemon not running [20081217-09:13:36.829938781] OPROFILE : using callgraph [5] [20081217-09:13:37.062749580] Daemon not running [20081217-09:13:37.064731253] Separate options: none [20081217-09:13:37.066947299] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-09:13:37.069011994] Image filter: none [20081217-09:13:37.070860445] Call-graph depth: 5 [20081217-09:13:37.129866533] FFSB version 6.0-RC2 started [20081217-09:13:37.132018676] [20081217-09:13:37.133921701] benchmark time = 300 [20081217-09:13:37.135913867] ThreadGroup 0 [20081217-09:13:37.137925474] ================ [20081217-09:13:37.139811725] num_threads = 1 [20081217-09:13:37.141696688] [20081217-09:13:37.143540622] read_random = off [20081217-09:13:37.145419678] read_size = 0 (0B) [20081217-09:13:37.147226356] read_blocksize = 0 (0B) [20081217-09:13:37.149056673] read_skip = off [20081217-09:13:37.150910103] read_skipsize = 0 (0B) [20081217-09:13:37.153163846] [20081217-09:13:37.155221940] write_random = on [20081217-09:13:37.157111235] write_size = 5242880 (5MB) [20081217-09:13:37.159073159] fsync_file = 0 [20081217-09:13:37.161052932] write_blocksize = 4096 (4KB) [20081217-09:13:37.163276011] wait time = 0 [20081217-09:13:37.165315393] [20081217-09:13:37.167302792] op weights [20081217-09:13:37.169378575] read = 0 (0.00%) [20081217-09:13:37.171157449] readall = 0 (0.00%) [20081217-09:13:37.173112352] write = 1 (100.00%) [20081217-09:13:37.174969512] create = 0 (0.00%) [20081217-09:13:37.176878254] append = 0 (0.00%) [20081217-09:13:37.178783950] delete = 0 (0.00%) [20081217-09:13:37.180725468] metaop = 0 (0.00%) [20081217-09:13:37.182728808] createdir = 0 (0.00%) [20081217-09:13:37.184710436] stat = 0 (0.00%) [20081217-09:13:37.186703932] writeall = 0 (0.00%) [20081217-09:13:37.188662750] writeall_fsync = 0 (0.00%) [20081217-09:13:37.190546434] open_close = 0 (0.00%) [20081217-09:13:37.192412992] write_fsync = 0 (0.00%) [20081217-09:13:37.194340212] create_fsync = 0 (0.00%) [20081217-09:13:37.196101113] append_fsync = 0 (0.00%) [20081217-09:13:37.198073473] [20081217-09:13:37.200101402] FileSystem /mnt/ffsb1 [20081217-09:13:37.202068229] ========== [20081217-09:13:37.203879141] num_dirs = 0 [20081217-09:13:37.205713652] starting files = 1024 [20081217-09:13:37.207512946] [20081217-09:13:37.209319350] min file size = 104857600 (100MB) [20081217-09:13:37.211051867] max file size = 104857600 (100MB) [20081217-09:13:37.212996832] directio = on [20081217-09:13:37.214920952] alignedio = on [20081217-09:13:37.216878390] bufferedio = off [20081217-09:13:37.218936541] [20081217-09:13:37.220776285] aging is off [20081217-09:13:37.222625126] current utilization = 4.84% [20081217-09:13:37.224422221] [20081217-09:13:37.226399335] checking existing fs: /mnt/ffsb1 [20081217-09:13:43.615840226] fs setup took 6 secs [20081217-09:13:44.003072605] Syncing()...0 sec [20081217-09:13:44.005124027] Starting Actual Benchmark At: Wed Dec 17 09:13:44 2008 [20081217-09:13:44.018273542] [20081217-09:18:51.296162125] Syncing()...3 sec [20081217-09:18:51.299254626] FFSB benchmark finished at: Wed Dec 17 09:18:51 2008 [20081217-09:18:51.302045308] [20081217-09:18:51.304493930] Results: [20081217-09:18:51.321496445] Benchmark took 307.29 sec [20081217-09:18:51.324246843] [20081217-09:18:51.326635399] Total Results [20081217-09:18:51.342430408] =============== [20081217-09:18:51.345988494] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-09:18:51.348822213] ======= ============ ========= ======= =========== ========== [20081217-09:18:51.351400076] write : 69120 224.93 100.000% 100.000% 17.6MB/sec [20081217-09:18:51.353921698] - [20081217-09:18:51.356616752] 224.93 Transactions per Second [20081217-09:18:51.359745388] [20081217-09:18:51.362146273] Throughput Results [20081217-09:18:51.377660722] =================== [20081217-09:18:51.380701382] Write Throughput: 17.6MB/sec [20081217-09:18:51.383356642] [20081217-09:18:51.386005866] System Call Latency statistics in millisecs [20081217-09:18:51.388841875] ===== [20081217-09:18:51.397674184] Min Avg Max Total Calls [20081217-09:18:51.400506977] ======== ======== ======== ============ [20081217-09:18:51.403538809] [ open] 0.018000 0.028278 0.039000 54 [20081217-09:18:51.408533997] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:18:51.411278327] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:18:51.414242523] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:18:51.417201986] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-09:18:51.419937094] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-09:18:51.422810543] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-09:18:51.425782556] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-09:18:51.428344244] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-09:18:51.430729140] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-09:18:51.432973635] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-09:18:51.435769936] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-09:18:51.438217485] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-09:18:51.440890656] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-09:18:51.443729477] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-09:18:51.446709604] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-09:18:51.449270966] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-09:18:51.451655179] msec_range[16] 0.020000 - 0.050000 : 52 [20081217-09:18:51.454035537] msec_range[17] 0.010000 - 0.020000 : 2 [20081217-09:18:51.456397999] msec_range[18] 0.000000 - 0.010000 : 0 [20081217-09:18:51.458670621] [20081217-09:18:51.461077673] [ write] 0.549000 4.392280 3076.493896 69120 [20081217-09:18:51.463521871] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:18:51.466798573] msec_range[1] 2000.000000 - 5000.000000 : 7 [20081217-09:18:51.469207364] msec_range[2] 1000.000000 - 2000.000000 : 1 [20081217-09:18:51.472103821] msec_range[3] 500.000000 - 1000.000000 : 4 [20081217-09:18:51.474864553] msec_range[4] 200.000000 - 500.000000 : 6 [20081217-09:18:51.477531890] msec_range[5] 100.000000 - 200.000000 : 3 [20081217-09:18:51.480070635] msec_range[6] 50.000000 - 100.000000 : 27 [20081217-09:18:51.483920142] msec_range[7] 20.000000 - 50.000000 : 183 [20081217-09:18:51.486349011] msec_range[8] 10.000000 - 20.000000 : 942 [20081217-09:18:51.488628809] msec_range[9] 5.000000 - 10.000000 : 3817 [20081217-09:18:51.490768170] msec_range[10] 2.000000 - 5.000000 : 63996 [20081217-09:18:51.493274094] msec_range[11] 1.000000 - 2.000000 : 104 [20081217-09:18:51.496924775] msec_range[12] 0.500000 - 1.000000 : 30 [20081217-09:18:51.499277016] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-09:18:51.501585869] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-09:18:51.504206568] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-09:18:51.506649597] msec_range[16] 0.020000 - 0.050000 : 0 [20081217-09:18:51.509656996] msec_range[17] 0.010000 - 0.020000 : 0 [20081217-09:18:51.512053795] msec_range[18] 0.000000 - 0.010000 : 0 [20081217-09:18:51.514522571] [20081217-09:18:51.517194024] [ lseek] 0.000000 0.001341 0.017000 69120 [20081217-09:18:51.520270029] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:18:51.522580301] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:18:51.525121719] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:18:51.527362857] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-09:18:51.530711841] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-09:18:51.533328252] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-09:18:51.535578738] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-09:18:51.539200377] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-09:18:51.541654875] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-09:18:51.544602561] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-09:18:51.547047797] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-09:18:51.549593520] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-09:18:51.552285303] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-09:18:51.554710355] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-09:18:51.557885664] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-09:18:51.561091188] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-09:18:51.563583576] msec_range[16] 0.020000 - 0.050000 : 0 [20081217-09:18:51.566232361] msec_range[17] 0.010000 - 0.020000 : 19 [20081217-09:18:51.570122361] msec_range[18] 0.000000 - 0.010000 : 69101 [20081217-09:18:51.573330045] [20081217-09:18:51.576034902] [ close] 0.005000 0.007148 0.012000 54 [20081217-09:18:51.578852439] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-09:18:51.582032995] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-09:18:51.584867378] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-09:18:51.587371429] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-09:18:51.591368303] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-09:18:51.594302601] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-09:18:51.597042480] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-09:18:51.599645874] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-09:18:51.602420109] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-09:18:51.605005829] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-09:18:51.607563632] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-09:18:51.611033214] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-09:18:51.613379142] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-09:18:51.615968503] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-09:18:51.619136072] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-09:18:51.622081963] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-09:18:51.624479567] msec_range[16] 0.020000 - 0.050000 : 0 [20081217-09:18:51.626972563] msec_range[17] 0.010000 - 0.020000 : 11 [20081217-09:18:51.629264873] msec_range[18] 0.000000 - 0.010000 : 43 [20081217-09:18:51.631532834] [20081217-09:18:51.633863662] [20081217-09:18:51.636102567] [20081217-09:18:51.638439940] [20081217-09:18:51.640849510] 0.0% User Time [20081217-09:18:51.643206047] 4.4% System Time [20081217-09:18:51.645462562] 4.4% CPU Utilization [20081217-09:18:51.647855705] Profilers reporting [20081217-09:19:08.441171452] Profilers postprocessing [20081217-09:19:09.579843811] Stopping profiling. [20081217-09:19:09.584574369] Killing daemon. [20081217-09:19:10.767178720] Processing File : /autobench/logs/ffsb.random_writes_odirect__threads_0001.08-12-17_09.13.26/analysis/oprofile.001 [20081217-09:19:10.769314190] Processing File : /autobench/logs/ffsb.random_writes_odirect__threads_0001.08-12-17_09.13.26/analysis/oprofile-brief.001 [20081217-09:19:10.885732882] Processing File : mpstat.001 [20081217-09:19:10.888024449] Discovered mpstat_interval=[5] [20081217-09:19:11.450439546] Processing Directory : sar.breakout.001 [20081217-09:19:11.452846004] Discovered sar_interval=[5] [20081217-09:19:11.592809052] Processing File : iostat.001 [20081217-09:19:11.595116474] Discovered iostat_interval=[5] [20081217-09:19:13.386788418] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0801/btrfs-baseline'