[20081217-03:00:00.982727817] PROCESSING COMMAND : 'clearprofilers' [20081217-03:00:01.236675276] PROCESSING COMMAND : 'useprofiler iostat 5' [20081217-03:00:01.343010277] Checking for sar... [20081217-03:00:01.345192357] found [20081217-03:00:01.480326692] PROCESSING COMMAND : 'useprofiler sar 5' [20081217-03:00:01.586394624] Checking for sar... [20081217-03:00:01.588563797] found [20081217-03:00:01.724570450] PROCESSING COMMAND : 'useprofiler mpstat 5' [20081217-03:00:01.830974135] Checking for sar... [20081217-03:00:01.833314181] found [20081217-03:00:02.000243948] PROCESSING COMMAND : 'useprofiler oprofile' [20081217-03:00:02.281942028] Checking for binutils-2.18 ... Already installed. [20081217-03:00:02.286285771] mv: cannot stat `lib64/*': No such file or directory [20081217-03:00:02.308807885] rmdir: lib64: No such file or directory [20081217-03:00:02.398696062] Checking for gettext-0.17 ... Already installed. [20081217-03:00:02.450737378] popt32-1.10.4 already installed. [20081217-03:00:02.465432986] popt64-1.10.4 already installed. [20081217-03:00:02.496019491] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-03:00:02.548661651] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-03:00:02.628220629] Daemon not running [20081217-03:00:02.649618857] Unloading oprofile module [20081217-03:00:02.847460983] Daemon not running [20081217-03:00:05.074501285] OPROFILE : using callgraph [5] [20081217-03:00:05.304455353] Daemon not running [20081217-03:00:05.306766632] Separate options: none [20081217-03:00:05.308970964] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-03:00:05.311133949] Image filter: none [20081217-03:00:05.313191426] Call-graph depth: 5 [20081217-03:00:05.514914277] PROCESSING COMMAND : 'umount /mnt/ffsb1 > /dev/null 2>&1' [20081217-03:00:05.590617910] PROCESSING COMMAND : 'set-sched noop' [20081217-03:00:05.989802035] PROCESSING COMMAND : 'mkresultdirs hks.austin.ibm.com benchmarks/results/btrfs/ffsb btrfs1 2008-12-17_0300 xfs-baseline' [20081217-03:00:06.208858361] Connecting to hks.austin.ibm.com... [20081217-03:00:06.211047650] Remote working directory: /opt [20081217-03:00:06.212925479] Remote working directory: /opt/benchmarks/results/btrfs/ffsb [20081217-03:00:06.214993931] Couldn't create directory: Failure [20081217-03:00:06.217303159] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1 [20081217-03:00:06.219372548] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs1 [20081217-03:00:06.221319675] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0300 [20081217-03:00:06.223088670] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0300 [20081217-03:00:06.225052896] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0300/xfs-baseline [20081217-03:00:06.297312136] PROCESSING COMMAND : 'mkfs.xfs -V 2>&1' [20081217-03:00:06.335800430] mkfs.xfs version 2.10.1 [20081217-03:00:06.431882543] PROCESSING COMMAND : 'mkfs.xfs -f /dev/ffsbdev1' [20081217-03:00:07.890083046] meta-data=/dev/ffsbdev1 isize=256 agcount=32, agsize=18327808 blks [20081217-03:00:07.893697409] = sectsz=512 attr=2 [20081217-03:00:07.895905686] data = bsize=4096 blocks=586489856, imaxpct=5 [20081217-03:00:07.898189621] = sunit=64 swidth=512 blks [20081217-03:00:07.900311794] naming =version 2 bsize=4096 ascii-ci=0 [20081217-03:00:07.902089156] log =internal log bsize=4096 blocks=32768, version=2 [20081217-03:00:07.904381775] = sectsz=512 sunit=64 blks, lazy-count=0 [20081217-03:00:07.906541310] realtime =none extsz=2097152 blocks=0, rtextents=0 [20081217-03:00:08.089100449] PROCESSING COMMAND : 'mount -t xfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-03:00:08.500794436] PROCESSING COMMAND : 'run sequential_reads__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb num_threads=1' [20081217-03:00:08.545700161] new log requested [20081217-03:00:08.569936438] Running command ffsb [20081217-03:00:18.259185324] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb [20081217-03:00:18.286090516] Importing argument : num_threads=1 [20081217-03:00:18.312534869] Found a xfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-03:00:18.400775804] Checking for sar... [20081217-03:00:18.402845863] found [20081217-03:00:18.459583000] Checking for sar... [20081217-03:00:18.462035457] found [20081217-03:00:18.517478312] Checking for sar... [20081217-03:00:18.527222457] found [20081217-03:00:18.659724139] Checking for binutils-2.18 ... Already installed. [20081217-03:00:18.663876293] mv: cannot stat `lib64/*': No such file or directory [20081217-03:00:18.666844444] rmdir: lib64: No such file or directory [20081217-03:00:18.726288968] Checking for gettext-0.17 ... Already installed. [20081217-03:00:18.767605866] popt32-1.10.4 already installed. [20081217-03:00:18.783107923] popt64-1.10.4 already installed. [20081217-03:00:18.813774418] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-03:00:18.866170157] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-03:00:18.947637349] Daemon not running [20081217-03:00:18.958136117] Unloading oprofile module [20081217-03:00:19.086380913] Daemon not running [20081217-03:00:19.319983284] OPROFILE : using callgraph [5] [20081217-03:00:19.553178445] Daemon not running [20081217-03:00:19.555281326] Separate options: none [20081217-03:00:19.557335068] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-03:00:19.559583245] Image filter: none [20081217-03:00:19.561739894] Call-graph depth: 5 [20081217-03:00:19.641297487] FFSB version 6.0-RC2 started [20081217-03:00:19.643470970] [20081217-03:00:19.645641585] benchmark time = 300 [20081217-03:00:19.647642420] ThreadGroup 0 [20081217-03:00:19.649876757] ================ [20081217-03:00:19.652089571] num_threads = 1 [20081217-03:00:19.654123675] [20081217-03:00:19.655991208] read_random = off [20081217-03:00:19.657883992] read_size = 0 (0B) [20081217-03:00:19.659702127] read_blocksize = 4096 (4KB) [20081217-03:00:19.661759291] read_skip = off [20081217-03:00:19.663737164] read_skipsize = 0 (0B) [20081217-03:00:19.665523722] [20081217-03:00:19.667415885] write_random = off [20081217-03:00:19.669294246] write_size = 0 (0B) [20081217-03:00:19.671058742] fsync_file = 0 [20081217-03:00:19.672936142] write_blocksize = 0 (0B) [20081217-03:00:19.674783401] wait time = 0 [20081217-03:00:19.676530529] [20081217-03:00:19.678394928] op weights [20081217-03:00:19.680229961] read = 0 (0.00%) [20081217-03:00:19.681983163] readall = 1 (100.00%) [20081217-03:00:19.683850485] write = 0 (0.00%) [20081217-03:00:19.685828124] create = 0 (0.00%) [20081217-03:00:19.687794528] append = 0 (0.00%) [20081217-03:00:19.689651677] delete = 0 (0.00%) [20081217-03:00:19.691542890] metaop = 0 (0.00%) [20081217-03:00:19.693363719] createdir = 0 (0.00%) [20081217-03:00:19.695254375] stat = 0 (0.00%) [20081217-03:00:19.697101776] writeall = 0 (0.00%) [20081217-03:00:19.698862093] writeall_fsync = 0 (0.00%) [20081217-03:00:19.700717413] open_close = 0 (0.00%) [20081217-03:00:19.702589621] write_fsync = 0 (0.00%) [20081217-03:00:19.704342175] create_fsync = 0 (0.00%) [20081217-03:00:19.706190355] append_fsync = 0 (0.00%) [20081217-03:00:19.708020414] [20081217-03:00:19.709918983] FileSystem /mnt/ffsb1 [20081217-03:00:19.711792133] ========== [20081217-03:00:19.713587942] num_dirs = 0 [20081217-03:00:19.715481448] starting files = 1024 [20081217-03:00:19.717267776] [20081217-03:00:19.719110491] min file size = 104857600 (100MB) [20081217-03:00:19.720926305] max file size = 104857600 (100MB) [20081217-03:00:19.722760655] directio = off [20081217-03:00:19.724604350] alignedio = on [20081217-03:00:19.726467781] bufferedio = off [20081217-03:00:19.728213072] [20081217-03:00:19.729939751] aging is off [20081217-03:00:19.731624071] current utilization = 0.00% [20081217-03:00:19.733481081] [20081217-03:00:19.735317028] checking existing fs: /mnt/ffsb1 [20081217-03:00:19.737032172] opendir: No such file or directory [20081217-03:00:19.738888718] recreating new fileset [20081217-03:06:02.636310669] fs setup took 342 secs [20081217-03:06:03.224226910] Syncing()...0 sec [20081217-03:06:03.226694891] Starting Actual Benchmark At: Wed Dec 17 03:06:03 2008 [20081217-03:06:03.304368400] [20081217-03:11:04.943109948] Syncing()...0 sec [20081217-03:11:05.041988837] FFSB benchmark finished at: Wed Dec 17 03:11:04 2008 [20081217-03:11:05.044835268] [20081217-03:11:05.047682659] Results: [20081217-03:11:05.108918310] Benchmark took 301.50 sec [20081217-03:11:05.111721397] [20081217-03:11:05.114301869] Total Results [20081217-03:11:05.129759817] =============== [20081217-03:11:05.132006253] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-03:11:05.134453778] ======= ============ ========= ======= =========== ========== [20081217-03:11:05.136896178] readall : 11980800 39736.67 100.000% 100.000% 155MB/sec [20081217-03:11:05.139200003] - [20081217-03:11:05.141315049] 39736.67 Transactions per Second [20081217-03:11:05.143578576] [20081217-03:11:05.145817233] Throughput Results [20081217-03:11:05.162229006] =================== [20081217-03:11:05.164761855] Read Throughput: 155MB/sec [20081217-03:11:05.167254988] [20081217-03:11:05.169920705] System Call Latency statistics in millisecs [20081217-03:11:05.172118565] ===== [20081217-03:11:05.174648204] Min Avg Max Total Calls [20081217-03:11:05.177163825] ======== ======== ======== ============ [20081217-03:11:05.179646770] [ open] 0.017000 0.163154 9.812000 468 [20081217-03:11:05.182245943] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:11:05.184471148] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:11:05.186682512] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:11:05.188906073] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:11:05.191014841] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:11:05.193212039] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:11:05.195339393] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:11:05.197523932] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-03:11:05.199625269] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-03:11:05.201874355] msec_range[9] 5.000000 - 10.000000 : 5 [20081217-03:11:05.204407132] msec_range[10] 2.000000 - 5.000000 : 2 [20081217-03:11:05.206997442] msec_range[11] 1.000000 - 2.000000 : 1 [20081217-03:11:05.209749351] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-03:11:05.212385070] msec_range[13] 0.200000 - 0.500000 : 2 [20081217-03:11:05.214841846] msec_range[14] 0.100000 - 0.200000 : 1 [20081217-03:11:05.217476604] msec_range[15] 0.050000 - 0.100000 : 355 [20081217-03:11:05.220092813] msec_range[16] 0.020000 - 0.050000 : 100 [20081217-03:11:05.223241837] msec_range[17] 0.010000 - 0.020000 : 2 [20081217-03:11:05.225920870] msec_range[18] 0.000000 - 0.010000 : 0 [20081217-03:11:05.228377712] [20081217-03:11:05.230956451] [ read] 0.004000 0.024784 312.401001 11980800 [20081217-03:11:05.233304160] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:11:05.235617181] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:11:05.237840646] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:11:05.240348270] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:11:05.243141879] msec_range[4] 200.000000 - 500.000000 : 76 [20081217-03:11:05.245516344] msec_range[5] 100.000000 - 200.000000 : 18 [20081217-03:11:05.248084843] msec_range[6] 50.000000 - 100.000000 : 6 [20081217-03:11:05.250469348] msec_range[7] 20.000000 - 50.000000 : 15 [20081217-03:11:05.252733793] msec_range[8] 10.000000 - 20.000000 : 597 [20081217-03:11:05.254876123] msec_range[9] 5.000000 - 10.000000 : 4395 [20081217-03:11:05.257116491] msec_range[10] 2.000000 - 5.000000 : 20785 [20081217-03:11:05.259239400] msec_range[11] 1.000000 - 2.000000 : 56906 [20081217-03:11:05.261405360] msec_range[12] 0.500000 - 1.000000 : 13119 [20081217-03:11:05.263527750] msec_range[13] 0.200000 - 0.500000 : 53838 [20081217-03:11:05.265799461] msec_range[14] 0.100000 - 0.200000 : 14917 [20081217-03:11:05.267973034] msec_range[15] 0.050000 - 0.100000 : 1366 [20081217-03:11:05.270170912] msec_range[16] 0.020000 - 0.050000 : 3446 [20081217-03:11:05.272243477] msec_range[17] 0.010000 - 0.020000 : 426053 [20081217-03:11:05.274467086] msec_range[18] 0.000000 - 0.010000 : 11385263 [20081217-03:11:05.276592018] [20081217-03:11:05.278868484] [ close] 0.007000 0.011731 0.022000 468 [20081217-03:11:05.281431137] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:11:05.283884508] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:11:05.286480474] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:11:05.288779335] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:11:05.290967200] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:11:05.293103511] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:11:05.295606783] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:11:05.297774859] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-03:11:05.299971130] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-03:11:05.302120917] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-03:11:05.304470887] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-03:11:05.306775158] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-03:11:05.309334461] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-03:11:05.311743707] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-03:11:05.314078646] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-03:11:05.316290317] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-03:11:05.318873237] msec_range[16] 0.020000 - 0.050000 : 6 [20081217-03:11:05.321265145] msec_range[17] 0.010000 - 0.020000 : 382 [20081217-03:11:05.323611970] msec_range[18] 0.000000 - 0.010000 : 80 [20081217-03:11:05.325910404] [20081217-03:11:05.327990256] [20081217-03:11:05.330810189] [20081217-03:11:05.333295134] [20081217-03:11:05.335515975] 2.6% User Time [20081217-03:11:05.337632694] 28.4% System Time [20081217-03:11:05.339837983] 31.0% CPU Utilization [20081217-03:11:05.342149655] Profilers reporting [20081217-03:11:25.001942035] Profilers postprocessing [20081217-03:11:26.139698111] Stopping profiling. [20081217-03:11:26.145156644] Killing daemon. [20081217-03:11:28.607502525] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0001.08-12-17_03.00.08/analysis/oprofile.001 [20081217-03:11:28.609701089] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0001.08-12-17_03.00.08/analysis/oprofile-brief.001 [20081217-03:11:28.814980330] Processing File : mpstat.001 [20081217-03:11:28.817058242] Discovered mpstat_interval=[5] [20081217-03:11:29.458161803] Processing Directory : sar.breakout.001 [20081217-03:11:29.460473546] Discovered sar_interval=[5] [20081217-03:11:29.676534828] Processing File : iostat.001 [20081217-03:11:29.678688270] Discovered iostat_interval=[5] [20081217-03:11:32.194036982] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0300/xfs-baseline' [20081217-03:11:36.684326049] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-03:11:37.663641988] PROCESSING COMMAND : 'mount -t xfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-03:11:37.938912800] PROCESSING COMMAND : 'run sequential_reads__threads_0016 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb num_threads=16' [20081217-03:11:37.984299550] new log requested [20081217-03:11:38.008464441] Running command ffsb [20081217-03:11:46.989747799] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb [20081217-03:11:47.014884946] Importing argument : num_threads=16 [20081217-03:11:47.041542143] Found a xfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-03:11:47.137141693] Checking for sar... [20081217-03:11:47.139247731] found [20081217-03:11:47.195501320] Checking for sar... [20081217-03:11:47.197822659] found [20081217-03:11:47.253159492] Checking for sar... [20081217-03:11:47.255238867] found [20081217-03:11:47.416340304] Checking for binutils-2.18 ... Already installed. [20081217-03:11:47.420805658] mv: cannot stat `lib64/*': No such file or directory [20081217-03:11:47.427642086] rmdir: lib64: No such file or directory [20081217-03:11:47.498766125] Checking for gettext-0.17 ... Already installed. [20081217-03:11:47.545219310] popt32-1.10.4 already installed. [20081217-03:11:47.560858158] popt64-1.10.4 already installed. [20081217-03:11:47.591742905] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-03:11:47.644384962] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-03:11:47.725624609] Daemon not running [20081217-03:11:47.743773272] Unloading oprofile module [20081217-03:11:47.994133670] Daemon not running [20081217-03:11:48.907295566] OPROFILE : using callgraph [5] [20081217-03:11:49.141307461] Daemon not running [20081217-03:11:49.143302192] Separate options: none [20081217-03:11:49.145437672] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-03:11:49.147599137] Image filter: none [20081217-03:11:49.149471557] Call-graph depth: 5 [20081217-03:11:49.229339839] FFSB version 6.0-RC2 started [20081217-03:11:49.231654929] [20081217-03:11:49.286546675] benchmark time = 300 [20081217-03:11:49.288455768] ThreadGroup 0 [20081217-03:11:49.290305428] ================ [20081217-03:11:49.292009576] num_threads = 16 [20081217-03:11:49.294155425] [20081217-03:11:49.296036647] read_random = off [20081217-03:11:49.297972363] read_size = 0 (0B) [20081217-03:11:49.299728844] read_blocksize = 4096 (4KB) [20081217-03:11:49.301549183] read_skip = off [20081217-03:11:49.303303853] read_skipsize = 0 (0B) [20081217-03:11:49.305069819] [20081217-03:11:49.306827090] write_random = off [20081217-03:11:49.308619945] write_size = 0 (0B) [20081217-03:11:49.310358072] fsync_file = 0 [20081217-03:11:49.312184792] write_blocksize = 0 (0B) [20081217-03:11:49.313934471] wait time = 0 [20081217-03:11:49.315733683] [20081217-03:11:49.317818027] op weights [20081217-03:11:49.319662440] read = 0 (0.00%) [20081217-03:11:49.321498558] readall = 1 (100.00%) [20081217-03:11:49.323352891] write = 0 (0.00%) [20081217-03:11:49.325124338] create = 0 (0.00%) [20081217-03:11:49.327085509] append = 0 (0.00%) [20081217-03:11:49.329077686] delete = 0 (0.00%) [20081217-03:11:49.330821846] metaop = 0 (0.00%) [20081217-03:11:49.332679102] createdir = 0 (0.00%) [20081217-03:11:49.334546340] stat = 0 (0.00%) [20081217-03:11:49.336262290] writeall = 0 (0.00%) [20081217-03:11:49.338105918] writeall_fsync = 0 (0.00%) [20081217-03:11:49.339928004] open_close = 0 (0.00%) [20081217-03:11:49.341671496] write_fsync = 0 (0.00%) [20081217-03:11:49.343507855] create_fsync = 0 (0.00%) [20081217-03:11:49.345303038] append_fsync = 0 (0.00%) [20081217-03:11:49.347012047] [20081217-03:11:49.348866614] FileSystem /mnt/ffsb1 [20081217-03:11:49.351177486] ========== [20081217-03:11:49.353376600] num_dirs = 0 [20081217-03:11:49.355143392] starting files = 1024 [20081217-03:11:49.356951126] [20081217-03:11:49.358797571] min file size = 104857600 (100MB) [20081217-03:11:49.360542996] max file size = 104857600 (100MB) [20081217-03:11:49.362377184] directio = off [20081217-03:11:49.364177738] alignedio = on [20081217-03:11:49.365906072] bufferedio = off [20081217-03:11:49.367715110] [20081217-03:11:49.369587049] aging is off [20081217-03:11:49.371545222] current utilization = 4.47% [20081217-03:11:49.373297413] [20081217-03:11:49.375055342] checking existing fs: /mnt/ffsb1 [20081217-03:11:49.394302022] fs setup took 0 secs [20081217-03:11:49.918406997] Syncing()...0 sec [20081217-03:11:49.920227589] Starting Actual Benchmark At: Wed Dec 17 03:11:49 2008 [20081217-03:11:49.933252923] [20081217-03:16:53.525476701] Syncing()...1 sec [20081217-03:16:53.582526663] FFSB benchmark finished at: Wed Dec 17 03:16:53 2008 [20081217-03:16:53.585373290] [20081217-03:16:53.588020581] Results: [20081217-03:16:53.702967278] Benchmark took 303.31 sec [20081217-03:16:53.705176359] [20081217-03:16:53.707816797] Total Results [20081217-03:16:53.722887043] =============== [20081217-03:16:53.725420650] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-03:16:53.728309151] ======= ============ ========= ======= =========== ========== [20081217-03:16:53.730634604] readall : 50176000 165428.70 100.000% 100.000% 646MB/sec [20081217-03:16:53.732963559] - [20081217-03:16:53.735193252] 165428.70 Transactions per Second [20081217-03:16:53.737588102] [20081217-03:16:53.739966969] Throughput Results [20081217-03:16:53.755091239] =================== [20081217-03:16:53.757202121] Read Throughput: 646MB/sec [20081217-03:16:53.759559107] [20081217-03:16:53.761825058] System Call Latency statistics in millisecs [20081217-03:16:53.764314088] ===== [20081217-03:16:53.766947279] Min Avg Max Total Calls [20081217-03:16:53.769137983] ======== ======== ======== ============ [20081217-03:16:53.771421068] [ open] 0.007000 1.223164 44.543999 1960 [20081217-03:16:53.773604712] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:16:53.775921705] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:16:53.778380036] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:16:53.781937520] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:16:53.784224473] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:16:53.787058529] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:16:53.789952113] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:16:53.792256953] msec_range[7] 20.000000 - 50.000000 : 21 [20081217-03:16:53.794400126] msec_range[8] 10.000000 - 20.000000 : 104 [20081217-03:16:53.796624965] msec_range[9] 5.000000 - 10.000000 : 38 [20081217-03:16:53.798739667] msec_range[10] 2.000000 - 5.000000 : 6 [20081217-03:16:53.800907572] msec_range[11] 1.000000 - 2.000000 : 1 [20081217-03:16:53.803066167] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-03:16:53.805249516] msec_range[13] 0.200000 - 0.500000 : 3 [20081217-03:16:53.807305386] msec_range[14] 0.100000 - 0.200000 : 89 [20081217-03:16:53.809431536] msec_range[15] 0.050000 - 0.100000 : 1026 [20081217-03:16:53.811534074] msec_range[16] 0.020000 - 0.050000 : 637 [20081217-03:16:53.814609123] msec_range[17] 0.010000 - 0.020000 : 16 [20081217-03:16:53.817297297] msec_range[18] 0.000000 - 0.010000 : 19 [20081217-03:16:53.820722778] [20081217-03:16:53.823209783] [ read] 0.002000 0.095723 175.686996 50176000 [20081217-03:16:53.825787343] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:16:53.828393284] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:16:53.849646655] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:16:53.852150489] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:16:53.854647200] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:16:53.857139506] msec_range[5] 100.000000 - 200.000000 : 27 [20081217-03:16:53.859344961] msec_range[6] 50.000000 - 100.000000 : 166 [20081217-03:16:53.861615373] msec_range[7] 20.000000 - 50.000000 : 26603 [20081217-03:16:53.863765657] msec_range[8] 10.000000 - 20.000000 : 148785 [20081217-03:16:53.866019447] msec_range[9] 5.000000 - 10.000000 : 160538 [20081217-03:16:53.868106273] msec_range[10] 2.000000 - 5.000000 : 127113 [20081217-03:16:53.870320464] msec_range[11] 1.000000 - 2.000000 : 50074 [20081217-03:16:53.872443151] msec_range[12] 0.500000 - 1.000000 : 29943 [20081217-03:16:53.874617836] msec_range[13] 0.200000 - 0.500000 : 199109 [20081217-03:16:53.876706825] msec_range[14] 0.100000 - 0.200000 : 10382 [20081217-03:16:53.878883988] msec_range[15] 0.050000 - 0.100000 : 73835 [20081217-03:16:53.880991792] msec_range[16] 0.020000 - 0.050000 : 173201 [20081217-03:16:53.883194618] msec_range[17] 0.010000 - 0.020000 : 3787251 [20081217-03:16:53.885264336] msec_range[18] 0.000000 - 0.010000 : 45388973 [20081217-03:16:53.887438633] [20081217-03:16:53.889590782] [ close] 0.003000 0.011264 0.058000 1960 [20081217-03:16:53.891947880] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:16:53.894199057] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:16:53.896619397] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:16:53.899075379] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:16:53.901499174] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:16:53.903937880] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:16:53.907677352] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:16:53.910096548] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-03:16:53.912824706] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-03:16:53.915339564] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-03:16:53.917667328] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-03:16:53.919837000] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-03:16:53.922099886] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-03:16:53.924336590] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-03:16:53.926817870] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-03:16:53.929155974] msec_range[15] 0.050000 - 0.100000 : 2 [20081217-03:16:53.931513148] msec_range[16] 0.020000 - 0.050000 : 21 [20081217-03:16:53.933825880] msec_range[17] 0.010000 - 0.020000 : 1489 [20081217-03:16:53.935991091] msec_range[18] 0.000000 - 0.010000 : 448 [20081217-03:16:53.938854685] [20081217-03:16:53.942423801] [20081217-03:16:53.944672344] [20081217-03:16:53.946892820] [20081217-03:16:53.949248746] 13.1% User Time [20081217-03:16:53.951579528] 140.9% System Time [20081217-03:16:53.953683095] 154.0% CPU Utilization [20081217-03:16:53.955964229] Profilers reporting [20081217-03:17:17.022260380] Profilers postprocessing [20081217-03:17:18.160180089] Stopping profiling. [20081217-03:17:18.165605535] Killing daemon. [20081217-03:17:20.652108947] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0016.08-12-17_03.11.37/analysis/oprofile.001 [20081217-03:17:20.654301189] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0016.08-12-17_03.11.37/analysis/oprofile-brief.001 [20081217-03:17:20.871574769] Processing File : mpstat.001 [20081217-03:17:20.873762594] Discovered mpstat_interval=[5] [20081217-03:17:21.521919660] Processing Directory : sar.breakout.001 [20081217-03:17:21.524184675] Discovered sar_interval=[5] [20081217-03:17:21.870608139] Processing File : iostat.001 [20081217-03:17:21.872817987] Discovered iostat_interval=[5] [20081217-03:17:24.152040068] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0300/xfs-baseline' [20081217-03:17:30.352351592] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-03:17:31.441700913] PROCESSING COMMAND : 'mount -t xfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-03:17:31.712012138] PROCESSING COMMAND : 'run sequential_reads__threads_0128 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb num_threads=128' [20081217-03:17:31.756671420] new log requested [20081217-03:17:31.780838653] Running command ffsb [20081217-03:17:41.267931029] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/sequential_reads.ffsb [20081217-03:17:41.284201223] Importing argument : num_threads=128 [20081217-03:17:41.309776914] Found a xfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-03:17:41.405499570] Checking for sar... [20081217-03:17:41.407738392] found [20081217-03:17:41.463588683] Checking for sar... [20081217-03:17:41.465730624] found [20081217-03:17:41.521457181] Checking for sar... [20081217-03:17:41.523546603] found [20081217-03:17:41.685460542] Checking for binutils-2.18 ... Already installed. [20081217-03:17:41.689873460] mv: cannot stat `lib64/*': No such file or directory [20081217-03:17:41.767405257] rmdir: lib64: No such file or directory [20081217-03:17:41.857362157] Checking for gettext-0.17 ... Already installed. [20081217-03:17:41.903751999] popt32-1.10.4 already installed. [20081217-03:17:41.918620674] popt64-1.10.4 already installed. [20081217-03:17:41.949799814] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-03:17:42.001936378] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-03:17:42.083809564] Daemon not running [20081217-03:17:42.101612364] Unloading oprofile module [20081217-03:17:42.334780676] Daemon not running [20081217-03:17:43.397511848] OPROFILE : using callgraph [5] [20081217-03:17:43.629915189] Daemon not running [20081217-03:17:43.632092491] Separate options: none [20081217-03:17:43.634103611] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-03:17:43.636296058] Image filter: none [20081217-03:17:43.638340592] Call-graph depth: 5 [20081217-03:17:43.711786532] FFSB version 6.0-RC2 started [20081217-03:17:43.713716921] [20081217-03:17:44.204176093] benchmark time = 300 [20081217-03:17:44.206347008] ThreadGroup 0 [20081217-03:17:44.208480605] ================ [20081217-03:17:44.210780932] num_threads = 128 [20081217-03:17:44.212889023] [20081217-03:17:44.214769355] read_random = off [20081217-03:17:44.216645959] read_size = 0 (0B) [20081217-03:17:44.218411517] read_blocksize = 4096 (4KB) [20081217-03:17:44.220296920] read_skip = off [20081217-03:17:44.222159014] read_skipsize = 0 (0B) [20081217-03:17:44.224014011] [20081217-03:17:44.225726338] write_random = off [20081217-03:17:44.227579302] write_size = 0 (0B) [20081217-03:17:44.229389800] fsync_file = 0 [20081217-03:17:44.231128659] write_blocksize = 0 (0B) [20081217-03:17:44.232953438] wait time = 0 [20081217-03:17:44.234768265] [20081217-03:17:44.236504854] op weights [20081217-03:17:44.238315141] read = 0 (0.00%) [20081217-03:17:44.240139722] readall = 1 (100.00%) [20081217-03:17:44.241856174] write = 0 (0.00%) [20081217-03:17:44.243686407] create = 0 (0.00%) [20081217-03:17:44.245486640] append = 0 (0.00%) [20081217-03:17:44.247199731] delete = 0 (0.00%) [20081217-03:17:44.249026728] metaop = 0 (0.00%) [20081217-03:17:44.250820666] createdir = 0 (0.00%) [20081217-03:17:44.252554822] stat = 0 (0.00%) [20081217-03:17:44.254377990] writeall = 0 (0.00%) [20081217-03:17:44.256226760] writeall_fsync = 0 (0.00%) [20081217-03:17:44.257964533] open_close = 0 (0.00%) [20081217-03:17:44.259840633] write_fsync = 0 (0.00%) [20081217-03:17:44.261663456] create_fsync = 0 (0.00%) [20081217-03:17:44.263389638] append_fsync = 0 (0.00%) [20081217-03:17:44.265247761] [20081217-03:17:44.267077309] FileSystem /mnt/ffsb1 [20081217-03:17:44.268910365] ========== [20081217-03:17:44.270603459] num_dirs = 0 [20081217-03:17:44.272478654] starting files = 1024 [20081217-03:17:44.274314924] [20081217-03:17:44.276064044] min file size = 104857600 (100MB) [20081217-03:17:44.277897158] max file size = 104857600 (100MB) [20081217-03:17:44.279686657] directio = off [20081217-03:17:44.281452053] alignedio = on [20081217-03:17:44.283280671] bufferedio = off [20081217-03:17:44.285095602] [20081217-03:17:44.286927229] aging is off [20081217-03:17:44.288666564] current utilization = 4.47% [20081217-03:17:44.290518338] [20081217-03:17:44.292350175] checking existing fs: /mnt/ffsb1 [20081217-03:17:44.312785518] fs setup took 0 secs [20081217-03:17:44.894462934] Syncing()...0 sec [20081217-03:17:44.901032965] Starting Actual Benchmark At: Wed Dec 17 03:17:44 2008 [20081217-03:17:44.914506040] [20081217-03:22:53.274134278] Syncing()...1 sec [20081217-03:22:53.324826432] FFSB benchmark finished at: Wed Dec 17 03:22:52 2008 [20081217-03:22:53.327676123] [20081217-03:22:53.330348809] Results: [20081217-03:22:53.379741304] Benchmark took 308.08 sec [20081217-03:22:53.382209502] [20081217-03:22:53.384946600] Total Results [20081217-03:22:53.399791487] =============== [20081217-03:22:53.401788515] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-03:22:53.404197039] ======= ============ ========= ======= =========== ========== [20081217-03:22:53.406612349] readall : 52454400 170262.53 100.000% 100.000% 665MB/sec [20081217-03:22:53.408750576] - [20081217-03:22:53.411242525] 170262.53 Transactions per Second [20081217-03:22:53.413601030] [20081217-03:22:53.415917555] Throughput Results [20081217-03:22:53.430784018] =================== [20081217-03:22:53.432889220] Read Throughput: 665MB/sec [20081217-03:22:53.435361284] [20081217-03:22:53.437623985] System Call Latency statistics in millisecs [20081217-03:22:53.439740245] ===== [20081217-03:22:53.442315053] Min Avg Max Total Calls [20081217-03:22:53.444674462] ======== ======== ======== ============ [20081217-03:22:53.446951935] [ open] 0.006000 73.854661 1147.068970 2049 [20081217-03:22:53.449062122] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:22:53.451331876] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:22:53.453501289] msec_range[2] 1000.000000 - 2000.000000 : 4 [20081217-03:22:53.455681772] msec_range[3] 500.000000 - 1000.000000 : 81 [20081217-03:22:53.457722859] msec_range[4] 200.000000 - 500.000000 : 199 [20081217-03:22:53.460406082] msec_range[5] 100.000000 - 200.000000 : 113 [20081217-03:22:53.463215958] msec_range[6] 50.000000 - 100.000000 : 72 [20081217-03:22:53.465393120] msec_range[7] 20.000000 - 50.000000 : 86 [20081217-03:22:53.467468447] msec_range[8] 10.000000 - 20.000000 : 60 [20081217-03:22:53.469687394] msec_range[9] 5.000000 - 10.000000 : 19 [20081217-03:22:53.471965573] msec_range[10] 2.000000 - 5.000000 : 7 [20081217-03:22:53.474468159] msec_range[11] 1.000000 - 2.000000 : 3 [20081217-03:22:53.476520193] msec_range[12] 0.500000 - 1.000000 : 3 [20081217-03:22:53.478813703] msec_range[13] 0.200000 - 0.500000 : 5 [20081217-03:22:53.480980921] msec_range[14] 0.100000 - 0.200000 : 112 [20081217-03:22:53.483043771] msec_range[15] 0.050000 - 0.100000 : 432 [20081217-03:22:53.485051803] msec_range[16] 0.020000 - 0.050000 : 678 [20081217-03:22:53.487294161] msec_range[17] 0.010000 - 0.020000 : 115 [20081217-03:22:53.489475707] msec_range[18] 0.000000 - 0.010000 : 60 [20081217-03:22:53.491593671] [20081217-03:22:53.493627246] [ read] 0.002000 0.740256 452.691010 52454400 [20081217-03:22:53.495849150] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:22:53.497960806] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:22:53.499966511] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:22:53.501956367] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:22:53.504141742] msec_range[4] 200.000000 - 500.000000 : 21283 [20081217-03:22:53.506226263] msec_range[5] 100.000000 - 200.000000 : 135787 [20081217-03:22:53.508182117] msec_range[6] 50.000000 - 100.000000 : 128247 [20081217-03:22:53.510168024] msec_range[7] 20.000000 - 50.000000 : 118175 [20081217-03:22:53.512377464] msec_range[8] 10.000000 - 20.000000 : 41332 [20081217-03:22:53.514451131] msec_range[9] 5.000000 - 10.000000 : 20696 [20081217-03:22:53.516390959] msec_range[10] 2.000000 - 5.000000 : 13289 [20081217-03:22:53.518349765] msec_range[11] 1.000000 - 2.000000 : 5503 [20081217-03:22:53.520669843] msec_range[12] 0.500000 - 1.000000 : 17604 [20081217-03:22:53.522955838] msec_range[13] 0.200000 - 0.500000 : 193074 [20081217-03:22:53.525079682] msec_range[14] 0.100000 - 0.200000 : 22639 [20081217-03:22:53.527404372] msec_range[15] 0.050000 - 0.100000 : 110714 [20081217-03:22:53.529550848] msec_range[16] 0.020000 - 0.050000 : 212188 [20081217-03:22:53.531560502] msec_range[17] 0.010000 - 0.020000 : 5297710 [20081217-03:22:53.533561954] msec_range[18] 0.000000 - 0.010000 : 46116159 [20081217-03:22:53.535779560] [20081217-03:22:53.537867396] [ close] 0.003000 0.011871 1.838000 2049 [20081217-03:22:53.539859232] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:22:53.541830812] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:22:53.544030338] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:22:53.546115006] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:22:53.548102829] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:22:53.550207791] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:22:53.552620491] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:22:53.556432243] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-03:22:53.558978431] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-03:22:53.561638677] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-03:22:53.564022684] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-03:22:53.566621172] msec_range[11] 1.000000 - 2.000000 : 1 [20081217-03:22:53.570192383] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-03:22:53.574295593] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-03:22:53.576906777] msec_range[14] 0.100000 - 0.200000 : 2 [20081217-03:22:53.579301412] msec_range[15] 0.050000 - 0.100000 : 1 [20081217-03:22:53.581606737] msec_range[16] 0.020000 - 0.050000 : 46 [20081217-03:22:53.583951353] msec_range[17] 0.010000 - 0.020000 : 1261 [20081217-03:22:53.586402845] msec_range[18] 0.000000 - 0.010000 : 738 [20081217-03:22:53.588607998] [20081217-03:22:53.590660095] [20081217-03:22:53.592704428] [20081217-03:22:53.594935304] [20081217-03:22:53.597012489] 14.2% User Time [20081217-03:22:53.599074643] 150.0% System Time [20081217-03:22:53.601037361] 164.3% CPU Utilization [20081217-03:22:53.664217779] Profilers reporting [20081217-03:23:27.967299816] Profilers postprocessing [20081217-03:23:29.104329847] Stopping profiling. [20081217-03:23:29.108554966] Killing daemon. [20081217-03:23:31.517963797] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0128.08-12-17_03.17.31/analysis/oprofile.001 [20081217-03:23:31.520132449] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0128.08-12-17_03.17.31/analysis/oprofile-brief.001 [20081217-03:23:31.703089482] Processing File : mpstat.001 [20081217-03:23:31.705318352] Discovered mpstat_interval=[5] [20081217-03:23:32.813344640] Processing Directory : sar.breakout.001 [20081217-03:23:32.815544224] Discovered sar_interval=[5] [20081217-03:23:33.136099914] Processing File : iostat.001 [20081217-03:23:33.138274932] Discovered iostat_interval=[5] [20081217-03:23:40.145284657] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0300/xfs-baseline' [20081217-03:23:44.306460882] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-03:23:45.455436688] PROCESSING COMMAND : 'mount -t xfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-03:23:45.729185180] PROCESSING COMMAND : 'run random_reads__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb num_threads=1' [20081217-03:23:45.774050062] new log requested [20081217-03:23:45.798467544] Running command ffsb [20081217-03:23:55.182921858] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb [20081217-03:23:55.203007956] Importing argument : num_threads=1 [20081217-03:23:55.228479649] Found a xfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-03:23:55.327328440] Checking for sar... [20081217-03:23:55.329495114] found [20081217-03:23:55.385501727] Checking for sar... [20081217-03:23:55.387632537] found [20081217-03:23:55.443849550] Checking for sar... [20081217-03:23:55.446282122] found [20081217-03:23:55.606987412] Checking for binutils-2.18 ... Already installed. [20081217-03:23:55.611273775] mv: cannot stat `lib64/*': No such file or directory [20081217-03:23:55.624050093] rmdir: lib64: No such file or directory [20081217-03:23:55.695199207] Checking for gettext-0.17 ... Already installed. [20081217-03:23:55.753668327] popt32-1.10.4 already installed. [20081217-03:23:55.800602654] popt64-1.10.4 already installed. [20081217-03:23:55.831482788] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-03:23:55.884133313] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-03:23:55.964141179] Daemon not running [20081217-03:23:55.981479706] Unloading oprofile module [20081217-03:23:56.191691972] Daemon not running [20081217-03:23:57.772313969] OPROFILE : using callgraph [5] [20081217-03:23:58.006735749] Daemon not running [20081217-03:23:58.008858822] Separate options: none [20081217-03:23:58.010881771] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-03:23:58.013045251] Image filter: none [20081217-03:23:58.014871151] Call-graph depth: 5 [20081217-03:23:58.094605709] FFSB version 6.0-RC2 started [20081217-03:23:58.096891092] [20081217-03:23:58.098675784] benchmark time = 300 [20081217-03:23:58.100770161] ThreadGroup 0 [20081217-03:23:58.102607166] ================ [20081217-03:23:58.104430386] num_threads = 1 [20081217-03:23:58.106448960] [20081217-03:23:58.108439109] read_random = on [20081217-03:23:58.110626484] read_size = 5242880 (5MB) [20081217-03:23:58.112639624] read_blocksize = 4096 (4KB) [20081217-03:23:58.114556526] read_skip = off [20081217-03:23:58.116292867] read_skipsize = 0 (0B) [20081217-03:23:58.118168312] [20081217-03:23:58.119970663] write_random = off [20081217-03:23:58.121815828] write_size = 0 (0B) [20081217-03:23:58.123534606] fsync_file = 0 [20081217-03:23:58.125338499] write_blocksize = 0 (0B) [20081217-03:23:58.127197090] wait time = 0 [20081217-03:23:58.128924320] [20081217-03:23:58.130765721] op weights [20081217-03:23:58.132590630] read = 1 (100.00%) [20081217-03:23:58.134462902] readall = 0 (0.00%) [20081217-03:23:58.136474915] write = 0 (0.00%) [20081217-03:23:58.138276315] create = 0 (0.00%) [20081217-03:23:58.140103626] append = 0 (0.00%) [20081217-03:23:58.141850696] delete = 0 (0.00%) [20081217-03:23:58.143716852] metaop = 0 (0.00%) [20081217-03:23:58.145521135] createdir = 0 (0.00%) [20081217-03:23:58.147216561] stat = 0 (0.00%) [20081217-03:23:58.149112199] writeall = 0 (0.00%) [20081217-03:23:58.150921408] writeall_fsync = 0 (0.00%) [20081217-03:23:58.152821716] open_close = 0 (0.00%) [20081217-03:23:58.154733418] write_fsync = 0 (0.00%) [20081217-03:23:58.156533823] create_fsync = 0 (0.00%) [20081217-03:23:58.158304049] append_fsync = 0 (0.00%) [20081217-03:23:58.160092819] [20081217-03:23:58.161961454] FileSystem /mnt/ffsb1 [20081217-03:23:58.163765119] ========== [20081217-03:23:58.165479591] num_dirs = 0 [20081217-03:23:58.167324105] starting files = 1024 [20081217-03:23:58.169108974] [20081217-03:23:58.170966062] min file size = 104857600 (100MB) [20081217-03:23:58.172892447] max file size = 104857600 (100MB) [20081217-03:23:58.174698097] directio = off [20081217-03:23:58.176516322] alignedio = on [20081217-03:23:58.178222163] bufferedio = off [20081217-03:23:58.180104071] [20081217-03:23:58.181900237] aging is off [20081217-03:23:58.183646610] current utilization = 4.47% [20081217-03:23:58.185471715] [20081217-03:23:58.187259737] checking existing fs: /mnt/ffsb1 [20081217-03:23:58.198006704] fs setup took 0 secs [20081217-03:23:59.129248835] Syncing()...0 sec [20081217-03:23:59.131093000] Starting Actual Benchmark At: Wed Dec 17 03:23:59 2008 [20081217-03:23:59.144395380] [20081217-03:29:01.136443886] Syncing()...0 sec [20081217-03:29:01.139433228] FFSB benchmark finished at: Wed Dec 17 03:29:01 2008 [20081217-03:29:01.142224126] [20081217-03:29:01.145055172] Results: [20081217-03:29:01.160353611] Benchmark took 302.01 sec [20081217-03:29:01.162758181] [20081217-03:29:01.165063195] Total Results [20081217-03:29:01.180538318] =============== [20081217-03:29:01.184637568] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-03:29:01.187243202] ======= ============ ========= ======= =========== ========== [20081217-03:29:01.189796790] read : 162560 538.27 100.000% 100.000% 2.1MB/sec [20081217-03:29:01.192697051] - [20081217-03:29:01.196003175] 538.27 Transactions per Second [20081217-03:29:01.199420123] [20081217-03:29:01.202787421] Throughput Results [20081217-03:29:01.219448992] =================== [20081217-03:29:01.222146102] Read Throughput: 2.1MB/sec [20081217-03:29:01.224590093] [20081217-03:29:01.227301877] System Call Latency statistics in millisecs [20081217-03:29:01.231190274] ===== [20081217-03:29:01.233905784] Min Avg Max Total Calls [20081217-03:29:01.236849509] ======== ======== ======== ============ [20081217-03:29:01.240318619] [ open] 0.013000 0.023276 0.282000 127 [20081217-03:29:01.243072052] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:29:01.246142012] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:29:01.248731319] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:29:01.251334409] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:29:01.253662742] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:29:01.256334876] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:29:01.260859052] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:29:01.264367818] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-03:29:01.267257721] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-03:29:01.270255491] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-03:29:01.273442035] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-03:29:01.276102902] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-03:29:01.278636806] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-03:29:01.281125536] msec_range[13] 0.200000 - 0.500000 : 1 [20081217-03:29:01.283561596] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-03:29:01.286074430] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-03:29:01.288641680] msec_range[16] 0.020000 - 0.050000 : 71 [20081217-03:29:01.291266227] msec_range[17] 0.010000 - 0.020000 : 55 [20081217-03:29:01.293644468] msec_range[18] 0.000000 - 0.010000 : 0 [20081217-03:29:01.296314548] [20081217-03:29:01.299504911] [ read] 0.002000 1.850123 29.485001 162560 [20081217-03:29:01.302229346] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:29:01.305445435] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:29:01.308491712] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:29:01.311194087] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:29:01.313808685] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:29:01.316238382] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:29:01.318884680] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:29:01.325891058] msec_range[7] 20.000000 - 50.000000 : 73 [20081217-03:29:01.329033761] msec_range[8] 10.000000 - 20.000000 : 583 [20081217-03:29:01.332443118] msec_range[9] 5.000000 - 10.000000 : 20692 [20081217-03:29:01.335352569] msec_range[10] 2.000000 - 5.000000 : 27665 [20081217-03:29:01.338654090] msec_range[11] 1.000000 - 2.000000 : 7042 [20081217-03:29:01.341427723] msec_range[12] 0.500000 - 1.000000 : 480 [20081217-03:29:01.344496754] msec_range[13] 0.200000 - 0.500000 : 99428 [20081217-03:29:01.347120254] msec_range[14] 0.100000 - 0.200000 : 775 [20081217-03:29:01.349359160] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-03:29:01.351881439] msec_range[16] 0.020000 - 0.050000 : 12 [20081217-03:29:01.354635180] msec_range[17] 0.010000 - 0.020000 : 910 [20081217-03:29:01.356956936] msec_range[18] 0.000000 - 0.010000 : 4900 [20081217-03:29:01.359387729] [20081217-03:29:01.363037003] [ lseek] 0.000000 0.001314 0.060000 162560 [20081217-03:29:01.365794545] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:29:01.368400790] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:29:01.372300500] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:29:01.374637751] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:29:01.377068948] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:29:01.379302237] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:29:01.382024086] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:29:01.384621000] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-03:29:01.387350190] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-03:29:01.389966015] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-03:29:01.392357286] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-03:29:01.394924286] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-03:29:01.397105923] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-03:29:01.399439936] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-03:29:01.402277993] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-03:29:01.404985528] msec_range[15] 0.050000 - 0.100000 : 1 [20081217-03:29:01.407745930] msec_range[16] 0.020000 - 0.050000 : 3 [20081217-03:29:01.410257232] msec_range[17] 0.010000 - 0.020000 : 85 [20081217-03:29:01.412590526] msec_range[18] 0.000000 - 0.010000 : 162471 [20081217-03:29:01.415133792] [20081217-03:29:01.417715244] [ close] 0.005000 0.008165 0.016000 127 [20081217-03:29:01.420638851] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:29:01.423239224] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:29:01.425866793] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:29:01.429120794] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:29:01.431638500] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:29:01.434327318] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:29:01.436994129] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:29:01.439400148] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-03:29:01.441813286] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-03:29:01.444370579] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-03:29:01.446984612] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-03:29:01.454236781] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-03:29:01.456533844] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-03:29:01.459023221] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-03:29:01.461469513] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-03:29:01.464095952] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-03:29:01.466471322] msec_range[16] 0.020000 - 0.050000 : 0 [20081217-03:29:01.468932598] msec_range[17] 0.010000 - 0.020000 : 30 [20081217-03:29:01.471460471] msec_range[18] 0.000000 - 0.010000 : 97 [20081217-03:29:01.474511455] [20081217-03:29:01.477061241] [20081217-03:29:01.479210974] [20081217-03:29:01.481407506] [20081217-03:29:01.483598098] 0.2% User Time [20081217-03:29:01.485685484] 2.0% System Time [20081217-03:29:01.487871219] 2.2% CPU Utilization [20081217-03:29:01.490043189] Profilers reporting [20081217-03:29:15.343149536] Profilers postprocessing [20081217-03:29:16.479971587] Stopping profiling. [20081217-03:29:16.484364045] Killing daemon. [20081217-03:29:17.659795479] Processing File : /autobench/logs/ffsb.random_reads__threads_0001.08-12-17_03.23.45/analysis/oprofile.001 [20081217-03:29:17.661956471] Processing File : /autobench/logs/ffsb.random_reads__threads_0001.08-12-17_03.23.45/analysis/oprofile-brief.001 [20081217-03:29:17.777705109] Processing File : mpstat.001 [20081217-03:29:17.779646349] Discovered mpstat_interval=[5] [20081217-03:29:18.322523841] Processing Directory : sar.breakout.001 [20081217-03:29:18.324967163] Discovered sar_interval=[5] [20081217-03:29:18.484277461] Processing File : iostat.001 [20081217-03:29:18.486629378] Discovered iostat_interval=[5] [20081217-03:29:20.109375502] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0300/xfs-baseline' [20081217-03:29:23.631589083] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-03:29:23.940491127] PROCESSING COMMAND : 'mount -t xfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-03:29:24.197064415] PROCESSING COMMAND : 'run random_reads__threads_0016 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb num_threads=16' [20081217-03:29:24.241901034] new log requested [20081217-03:29:24.266303542] Running command ffsb [20081217-03:29:32.951396554] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb [20081217-03:29:32.965818781] Importing argument : num_threads=16 [20081217-03:29:32.991725591] Found a xfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-03:29:33.080263864] Checking for sar... [20081217-03:29:33.082253089] found [20081217-03:29:33.139489661] Checking for sar... [20081217-03:29:33.141862300] found [20081217-03:29:33.197292762] Checking for sar... [20081217-03:29:33.199499118] found [20081217-03:29:33.329491492] Checking for binutils-2.18 ... Already installed. [20081217-03:29:33.333958009] mv: cannot stat `lib64/*': No such file or directory [20081217-03:29:33.336689114] rmdir: lib64: No such file or directory [20081217-03:29:33.396496184] Checking for gettext-0.17 ... Already installed. [20081217-03:29:33.437692829] popt32-1.10.4 already installed. [20081217-03:29:33.453353639] popt64-1.10.4 already installed. [20081217-03:29:33.484204598] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-03:29:33.536454632] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-03:29:33.616720843] Daemon not running [20081217-03:29:33.627563666] Unloading oprofile module [20081217-03:29:33.740635790] Daemon not running [20081217-03:29:34.552038298] OPROFILE : using callgraph [5] [20081217-03:29:34.782904954] Daemon not running [20081217-03:29:34.784947729] Separate options: none [20081217-03:29:34.787123884] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-03:29:34.788994392] Image filter: none [20081217-03:29:34.790626120] Call-graph depth: 5 [20081217-03:29:34.850482227] FFSB version 6.0-RC2 started [20081217-03:29:34.852696985] [20081217-03:29:34.912426280] benchmark time = 300 [20081217-03:29:34.914690098] ThreadGroup 0 [20081217-03:29:34.916764799] ================ [20081217-03:29:34.919011419] num_threads = 16 [20081217-03:29:34.920960995] [20081217-03:29:34.923140321] read_random = on [20081217-03:29:34.925052823] read_size = 5242880 (5MB) [20081217-03:29:34.926943494] read_blocksize = 4096 (4KB) [20081217-03:29:34.928748569] read_skip = off [20081217-03:29:34.930572096] read_skipsize = 0 (0B) [20081217-03:29:34.932325508] [20081217-03:29:34.934149190] write_random = off [20081217-03:29:34.936050942] write_size = 0 (0B) [20081217-03:29:34.937816086] fsync_file = 0 [20081217-03:29:34.939763409] write_blocksize = 0 (0B) [20081217-03:29:34.941565247] wait time = 0 [20081217-03:29:34.943419553] [20081217-03:29:34.945186103] op weights [20081217-03:29:34.947048891] read = 1 (100.00%) [20081217-03:29:34.948924565] readall = 0 (0.00%) [20081217-03:29:34.950721789] write = 0 (0.00%) [20081217-03:29:34.952602110] create = 0 (0.00%) [20081217-03:29:34.954392661] append = 0 (0.00%) [20081217-03:29:34.956231408] delete = 0 (0.00%) [20081217-03:29:34.957980913] metaop = 0 (0.00%) [20081217-03:29:34.959788563] createdir = 0 (0.00%) [20081217-03:29:34.961680137] stat = 0 (0.00%) [20081217-03:29:34.963455511] writeall = 0 (0.00%) [20081217-03:29:34.965386811] writeall_fsync = 0 (0.00%) [20081217-03:29:34.967173257] open_close = 0 (0.00%) [20081217-03:29:34.968990630] write_fsync = 0 (0.00%) [20081217-03:29:34.970744887] create_fsync = 0 (0.00%) [20081217-03:29:34.972624330] append_fsync = 0 (0.00%) [20081217-03:29:34.974503069] [20081217-03:29:34.976325948] FileSystem /mnt/ffsb1 [20081217-03:29:34.978221067] ========== [20081217-03:29:34.979965617] num_dirs = 0 [20081217-03:29:34.981749736] starting files = 1024 [20081217-03:29:34.983614580] [20081217-03:29:34.985367278] min file size = 104857600 (100MB) [20081217-03:29:34.987200456] max file size = 104857600 (100MB) [20081217-03:29:34.988908567] directio = off [20081217-03:29:34.991474618] alignedio = on [20081217-03:29:34.993535941] bufferedio = off [20081217-03:29:34.995336279] [20081217-03:29:34.997058565] aging is off [20081217-03:29:34.998857854] current utilization = 4.47% [20081217-03:29:35.000750141] [20081217-03:29:35.002559028] checking existing fs: /mnt/ffsb1 [20081217-03:29:35.016131085] fs setup took 0 secs [20081217-03:29:35.548367168] Syncing()...0 sec [20081217-03:29:35.550312413] Starting Actual Benchmark At: Wed Dec 17 03:29:35 2008 [20081217-03:29:35.563481130] [20081217-03:34:42.037613096] Syncing()...0 sec [20081217-03:34:42.049010683] FFSB benchmark finished at: Wed Dec 17 03:34:42 2008 [20081217-03:34:42.051359607] [20081217-03:34:42.053892059] Results: [20081217-03:34:42.069130166] Benchmark took 306.49 sec [20081217-03:34:42.072365087] [20081217-03:34:42.074985625] Total Results [20081217-03:34:42.090784716] =============== [20081217-03:34:42.093312954] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-03:34:42.095956972] ======= ============ ========= ======= =========== ========== [20081217-03:34:42.098884464] read : 1091840 3562.43 100.000% 100.000% 13.9MB/sec [20081217-03:34:42.101653007] - [20081217-03:34:42.104271884] 3562.43 Transactions per Second [20081217-03:34:42.107075420] [20081217-03:34:42.109680130] Throughput Results [20081217-03:34:42.126594575] =================== [20081217-03:34:42.129595276] Read Throughput: 13.9MB/sec [20081217-03:34:42.132631527] [20081217-03:34:42.135227236] System Call Latency statistics in millisecs [20081217-03:34:42.137959969] ===== [20081217-03:34:42.141242444] Min Avg Max Total Calls [20081217-03:34:42.145754057] ======== ======== ======== ============ [20081217-03:34:42.148454078] [ open] 0.006000 0.023864 0.097000 853 [20081217-03:34:42.151150702] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:34:42.154070258] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:34:42.156966857] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:34:42.159592999] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:34:42.163197490] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:34:42.166475070] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:34:42.170608324] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:34:42.173749108] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-03:34:42.180390313] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-03:34:42.183225945] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-03:34:42.186398627] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-03:34:42.189015663] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-03:34:42.191466691] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-03:34:42.194392279] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-03:34:42.197227158] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-03:34:42.202346076] msec_range[15] 0.050000 - 0.100000 : 31 [20081217-03:34:42.205754605] msec_range[16] 0.020000 - 0.050000 : 572 [20081217-03:34:42.208412129] msec_range[17] 0.010000 - 0.020000 : 226 [20081217-03:34:42.211150420] msec_range[18] 0.000000 - 0.010000 : 24 [20081217-03:34:42.213827687] [20081217-03:34:42.216462169] [ read] 0.002000 4.449055 46.691002 1091840 [20081217-03:34:42.219019133] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:34:42.221487405] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:34:42.224003982] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:34:42.226348395] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:34:42.228895908] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:34:42.231519563] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:34:42.234101350] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:34:42.237349991] msec_range[7] 20.000000 - 50.000000 : 807 [20081217-03:34:42.240114146] msec_range[8] 10.000000 - 20.000000 : 34412 [20081217-03:34:42.242599561] msec_range[9] 5.000000 - 10.000000 : 501097 [20081217-03:34:42.245294576] msec_range[10] 2.000000 - 5.000000 : 215725 [20081217-03:34:42.249536482] msec_range[11] 1.000000 - 2.000000 : 16837 [20081217-03:34:42.252252368] msec_range[12] 0.500000 - 1.000000 : 5823 [20081217-03:34:42.255086510] msec_range[13] 0.200000 - 0.500000 : 264861 [20081217-03:34:42.257759079] msec_range[14] 0.100000 - 0.200000 : 396 [20081217-03:34:42.260325795] msec_range[15] 0.050000 - 0.100000 : 16 [20081217-03:34:42.262581682] msec_range[16] 0.020000 - 0.050000 : 525 [20081217-03:34:42.266201882] msec_range[17] 0.010000 - 0.020000 : 11321 [20081217-03:34:42.269274060] msec_range[18] 0.000000 - 0.010000 : 40020 [20081217-03:34:42.272595560] [20081217-03:34:42.276715884] [ lseek] 0.000000 0.001395 0.170000 1091840 [20081217-03:34:42.279509115] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:34:42.282312560] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:34:42.285190567] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:34:42.289114341] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:34:42.293545672] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:34:42.296676992] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:34:42.300246012] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:34:42.304025429] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-03:34:42.309763679] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-03:34:42.312562488] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-03:34:42.315341817] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-03:34:42.318208263] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-03:34:42.320951993] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-03:34:42.323461403] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-03:34:42.326396965] msec_range[14] 0.100000 - 0.200000 : 3 [20081217-03:34:42.330083038] msec_range[15] 0.050000 - 0.100000 : 27 [20081217-03:34:42.332899479] msec_range[16] 0.020000 - 0.050000 : 667 [20081217-03:34:42.335631169] msec_range[17] 0.010000 - 0.020000 : 666 [20081217-03:34:42.338192027] msec_range[18] 0.000000 - 0.010000 : 1090477 [20081217-03:34:42.340689571] [20081217-03:34:42.343363567] [ close] 0.003000 0.008917 0.046000 853 [20081217-03:34:42.346060689] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:34:42.348608676] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:34:42.350992140] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:34:42.353525439] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:34:42.355833343] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:34:42.358239397] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:34:42.360590071] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:34:42.363070031] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-03:34:42.365668802] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-03:34:42.368243970] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-03:34:42.371143691] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-03:34:42.373607617] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-03:34:42.375897346] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-03:34:42.378133935] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-03:34:42.380416096] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-03:34:42.382730595] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-03:34:42.385136092] msec_range[16] 0.020000 - 0.050000 : 8 [20081217-03:34:42.387498319] msec_range[17] 0.010000 - 0.020000 : 228 [20081217-03:34:42.389750677] msec_range[18] 0.000000 - 0.010000 : 617 [20081217-03:34:42.391980354] [20081217-03:34:42.394094464] [20081217-03:34:42.396290891] [20081217-03:34:42.398465677] [20081217-03:34:42.400502824] 1.1% User Time [20081217-03:34:42.402752183] 15.7% System Time [20081217-03:34:42.404915132] 16.8% CPU Utilization [20081217-03:34:42.406969727] Profilers reporting [20081217-03:34:58.040437687] Profilers postprocessing [20081217-03:34:59.176156273] Stopping profiling. [20081217-03:34:59.181295229] Killing daemon. [20081217-03:35:00.355759799] Processing File : /autobench/logs/ffsb.random_reads__threads_0016.08-12-17_03.29.24/analysis/oprofile.001 [20081217-03:35:00.357978797] Processing File : /autobench/logs/ffsb.random_reads__threads_0016.08-12-17_03.29.24/analysis/oprofile-brief.001 [20081217-03:35:00.480633939] Processing File : mpstat.001 [20081217-03:35:00.483002097] Discovered mpstat_interval=[5] [20081217-03:35:01.040844436] Processing Directory : sar.breakout.001 [20081217-03:35:01.043138974] Discovered sar_interval=[5] [20081217-03:35:01.184976418] Processing File : iostat.001 [20081217-03:35:01.187288522] Discovered iostat_interval=[5] [20081217-03:35:02.635237651] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0300/xfs-baseline' [20081217-03:35:06.883541296] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-03:35:08.310786626] PROCESSING COMMAND : 'mount -t xfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-03:35:08.580280794] PROCESSING COMMAND : 'run random_reads__threads_0128 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb num_threads=128' [20081217-03:35:08.625256615] new log requested [20081217-03:35:08.649464353] Running command ffsb [20081217-03:35:17.278533414] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_reads.ffsb [20081217-03:35:17.293171557] Importing argument : num_threads=128 [20081217-03:35:17.319648215] Found a xfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-03:35:17.407892221] Checking for sar... [20081217-03:35:17.409988091] found [20081217-03:35:17.466847165] Checking for sar... [20081217-03:35:17.469160356] found [20081217-03:35:17.525077559] Checking for sar... [20081217-03:35:17.527223208] found [20081217-03:35:17.673242123] Checking for binutils-2.18 ... Already installed. [20081217-03:35:17.677529582] mv: cannot stat `lib64/*': No such file or directory [20081217-03:35:17.680305691] rmdir: lib64: No such file or directory [20081217-03:35:17.740381854] Checking for gettext-0.17 ... Already installed. [20081217-03:35:17.781410321] popt32-1.10.4 already installed. [20081217-03:35:17.796760474] popt64-1.10.4 already installed. [20081217-03:35:17.827406502] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-03:35:17.880291827] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-03:35:17.960391017] Daemon not running [20081217-03:35:17.970873645] Unloading oprofile module [20081217-03:35:18.109983684] Daemon not running [20081217-03:35:19.271042705] OPROFILE : using callgraph [5] [20081217-03:35:19.503138040] Daemon not running [20081217-03:35:19.505260284] Separate options: none [20081217-03:35:19.507342596] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-03:35:19.509414523] Image filter: none [20081217-03:35:19.511571011] Call-graph depth: 5 [20081217-03:35:19.570178940] FFSB version 6.0-RC2 started [20081217-03:35:19.572411327] [20081217-03:35:20.065220449] benchmark time = 300 [20081217-03:35:20.067184463] ThreadGroup 0 [20081217-03:35:20.069367406] ================ [20081217-03:35:20.071479463] num_threads = 128 [20081217-03:35:20.073821899] [20081217-03:35:20.075741272] read_random = on [20081217-03:35:20.077579205] read_size = 5242880 (5MB) [20081217-03:35:20.079353962] read_blocksize = 4096 (4KB) [20081217-03:35:20.081247987] read_skip = off [20081217-03:35:20.083028520] read_skipsize = 0 (0B) [20081217-03:35:20.084856997] [20081217-03:35:20.086829931] write_random = off [20081217-03:35:20.088735257] write_size = 0 (0B) [20081217-03:35:20.090658793] fsync_file = 0 [20081217-03:35:20.092558191] write_blocksize = 0 (0B) [20081217-03:35:20.094274012] wait time = 0 [20081217-03:35:20.096171385] [20081217-03:35:20.098035318] op weights [20081217-03:35:20.099784488] read = 1 (100.00%) [20081217-03:35:20.101647877] readall = 0 (0.00%) [20081217-03:35:20.103486424] write = 0 (0.00%) [20081217-03:35:20.105220495] create = 0 (0.00%) [20081217-03:35:20.107072835] append = 0 (0.00%) [20081217-03:35:20.108888846] delete = 0 (0.00%) [20081217-03:35:20.110765410] metaop = 0 (0.00%) [20081217-03:35:20.112644090] createdir = 0 (0.00%) [20081217-03:35:20.114401705] stat = 0 (0.00%) [20081217-03:35:20.116323197] writeall = 0 (0.00%) [20081217-03:35:20.118098289] writeall_fsync = 0 (0.00%) [20081217-03:35:20.119966644] open_close = 0 (0.00%) [20081217-03:35:20.122064844] write_fsync = 0 (0.00%) [20081217-03:35:20.123943380] create_fsync = 0 (0.00%) [20081217-03:35:20.125782999] append_fsync = 0 (0.00%) [20081217-03:35:20.127628209] [20081217-03:35:20.129506388] FileSystem /mnt/ffsb1 [20081217-03:35:20.131287585] ========== [20081217-03:35:20.133164090] num_dirs = 0 [20081217-03:35:20.135024142] starting files = 1024 [20081217-03:35:20.136792327] [20081217-03:35:20.138639611] min file size = 104857600 (100MB) [20081217-03:35:20.140412431] max file size = 104857600 (100MB) [20081217-03:35:20.142298897] directio = off [20081217-03:35:20.144034440] alignedio = on [20081217-03:35:20.145827800] bufferedio = off [20081217-03:35:20.147703320] [20081217-03:35:20.149438937] aging is off [20081217-03:35:20.151289436] current utilization = 4.47% [20081217-03:35:20.153152849] [20081217-03:35:20.154883813] checking existing fs: /mnt/ffsb1 [20081217-03:35:20.171820268] fs setup took 0 secs [20081217-03:35:20.529069840] Syncing()...0 sec [20081217-03:35:20.535305390] Starting Actual Benchmark At: Wed Dec 17 03:35:20 2008 [20081217-03:35:20.549209629] [20081217-03:40:32.527224576] Syncing()...2 sec [20081217-03:40:32.561311223] FFSB benchmark finished at: Wed Dec 17 03:40:32 2008 [20081217-03:40:32.564157473] [20081217-03:40:32.566882311] Results: [20081217-03:40:32.639387380] Benchmark took 311.79 sec [20081217-03:40:32.641824881] [20081217-03:40:32.643890239] Total Results [20081217-03:40:32.659381604] =============== [20081217-03:40:32.661974545] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-03:40:32.664456879] ======= ============ ========= ======= =========== ========== [20081217-03:40:32.666849856] read : 4432640 14216.77 100.000% 100.000% 55.5MB/sec [20081217-03:40:32.669325732] - [20081217-03:40:32.671762728] 14216.77 Transactions per Second [20081217-03:40:32.674282403] [20081217-03:40:32.676803126] Throughput Results [20081217-03:40:32.692678218] =================== [20081217-03:40:32.694854010] Read Throughput: 55.5MB/sec [20081217-03:40:32.697108230] [20081217-03:40:32.699274898] System Call Latency statistics in millisecs [20081217-03:40:32.701633729] ===== [20081217-03:40:32.703993614] Min Avg Max Total Calls [20081217-03:40:32.706490592] ======== ======== ======== ============ [20081217-03:40:32.709033991] [ open] 0.006000 0.071489 20.726999 3463 [20081217-03:40:32.711386875] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:40:32.713760337] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:40:32.715921615] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:40:32.718165824] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:40:32.720346838] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:40:32.722643336] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:40:32.724770747] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:40:32.726920251] msec_range[7] 20.000000 - 50.000000 : 1 [20081217-03:40:32.729031258] msec_range[8] 10.000000 - 20.000000 : 2 [20081217-03:40:32.731279407] msec_range[9] 5.000000 - 10.000000 : 6 [20081217-03:40:32.734441928] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-03:40:32.736849825] msec_range[11] 1.000000 - 2.000000 : 3 [20081217-03:40:32.739509302] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-03:40:32.742269776] msec_range[13] 0.200000 - 0.500000 : 2 [20081217-03:40:32.744642916] msec_range[14] 0.100000 - 0.200000 : 157 [20081217-03:40:32.747042034] msec_range[15] 0.050000 - 0.100000 : 1099 [20081217-03:40:32.749421123] msec_range[16] 0.020000 - 0.050000 : 1743 [20081217-03:40:32.751999754] msec_range[17] 0.010000 - 0.020000 : 350 [20081217-03:40:32.754309640] msec_range[18] 0.000000 - 0.010000 : 100 [20081217-03:40:32.756636282] [20081217-03:40:32.758742678] [ read] 0.002000 8.817418 293.705994 4432640 [20081217-03:40:32.760971242] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:40:32.857247063] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:40:32.859798671] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:40:32.862298007] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:40:32.865085671] msec_range[4] 200.000000 - 500.000000 : 9 [20081217-03:40:32.867720507] msec_range[5] 100.000000 - 200.000000 : 51 [20081217-03:40:32.870143001] msec_range[6] 50.000000 - 100.000000 : 2845 [20081217-03:40:32.872570163] msec_range[7] 20.000000 - 50.000000 : 194715 [20081217-03:40:32.875130246] msec_range[8] 10.000000 - 20.000000 : 1149218 [20081217-03:40:32.877429509] msec_range[9] 5.000000 - 10.000000 : 2229927 [20081217-03:40:32.880086287] msec_range[10] 2.000000 - 5.000000 : 540839 [20081217-03:40:32.882487020] msec_range[11] 1.000000 - 2.000000 : 19934 [20081217-03:40:32.884740837] msec_range[12] 0.500000 - 1.000000 : 7548 [20081217-03:40:32.886882855] msec_range[13] 0.200000 - 0.500000 : 32476 [20081217-03:40:32.889193095] msec_range[14] 0.100000 - 0.200000 : 461 [20081217-03:40:32.891408140] msec_range[15] 0.050000 - 0.100000 : 924 [20081217-03:40:32.893618611] msec_range[16] 0.020000 - 0.050000 : 8394 [20081217-03:40:32.895740935] msec_range[17] 0.010000 - 0.020000 : 59228 [20081217-03:40:32.898123147] msec_range[18] 0.000000 - 0.010000 : 186071 [20081217-03:40:32.900464744] [20081217-03:40:32.902779127] [ lseek] 0.000000 0.001640 0.603000 4432640 [20081217-03:40:32.904952943] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:40:32.907285629] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:40:32.909400948] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:40:32.911644414] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:40:32.913821614] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:40:32.916149453] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:40:32.918335452] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:40:32.920703550] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-03:40:32.922941184] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-03:40:32.925248480] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-03:40:32.927503851] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-03:40:32.929828563] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-03:40:32.932043194] msec_range[12] 0.500000 - 1.000000 : 1 [20081217-03:40:32.934344909] msec_range[13] 0.200000 - 0.500000 : 5 [20081217-03:40:32.936591918] msec_range[14] 0.100000 - 0.200000 : 83 [20081217-03:40:32.938902326] msec_range[15] 0.050000 - 0.100000 : 1252 [20081217-03:40:32.941131937] msec_range[16] 0.020000 - 0.050000 : 15088 [20081217-03:40:32.943444898] msec_range[17] 0.010000 - 0.020000 : 5734 [20081217-03:40:32.945820125] msec_range[18] 0.000000 - 0.010000 : 4410477 [20081217-03:40:32.947933364] [20081217-03:40:32.950342017] [ close] 0.003000 0.010373 0.167000 3463 [20081217-03:40:32.952692394] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:40:32.954987550] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:40:32.957086071] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:40:32.959295508] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:40:32.961514842] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:40:32.963916565] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:40:32.966195000] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:40:32.968610761] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-03:40:32.970882081] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-03:40:32.973012977] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-03:40:32.975879176] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-03:40:32.978742794] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-03:40:32.981072985] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-03:40:32.983233942] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-03:40:32.985513742] msec_range[14] 0.100000 - 0.200000 : 1 [20081217-03:40:32.987819472] msec_range[15] 0.050000 - 0.100000 : 19 [20081217-03:40:32.990266627] msec_range[16] 0.020000 - 0.050000 : 92 [20081217-03:40:32.992514448] msec_range[17] 0.010000 - 0.020000 : 1236 [20081217-03:40:32.995729963] msec_range[18] 0.000000 - 0.010000 : 2115 [20081217-03:40:32.998074787] [20081217-03:40:33.000476907] [20081217-03:40:33.003742753] [20081217-03:40:33.006462516] [20081217-03:40:33.009097109] 4.9% User Time [20081217-03:40:33.011533070] 72.4% System Time [20081217-03:40:33.014836564] 77.3% CPU Utilization [20081217-03:40:33.017887954] Profilers reporting [20081217-03:40:59.289366179] Profilers postprocessing [20081217-03:41:00.426029351] Stopping profiling. [20081217-03:41:00.430694632] Killing daemon. [20081217-03:41:03.032501273] Processing File : /autobench/logs/ffsb.random_reads__threads_0128.08-12-17_03.35.08/analysis/oprofile.001 [20081217-03:41:03.034753150] Processing File : /autobench/logs/ffsb.random_reads__threads_0128.08-12-17_03.35.08/analysis/oprofile-brief.001 [20081217-03:41:03.228214848] Processing File : mpstat.001 [20081217-03:41:03.230316582] Discovered mpstat_interval=[5] [20081217-03:41:04.218144742] Processing Directory : sar.breakout.001 [20081217-03:41:04.220374941] Discovered sar_interval=[5] [20081217-03:41:04.508228976] Processing File : iostat.001 [20081217-03:41:04.510376852] Discovered iostat_interval=[5] [20081217-03:41:06.900020705] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0300/xfs-baseline' [20081217-03:41:12.011458760] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-03:41:13.822746779] PROCESSING COMMAND : 'mount -t xfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-03:41:14.100254355] PROCESSING COMMAND : 'run random_writes__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb num_threads=1' [20081217-03:41:14.145017713] new log requested [20081217-03:41:14.169423242] Running command ffsb [20081217-03:41:23.704618369] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb [20081217-03:41:23.720782652] Importing argument : num_threads=1 [20081217-03:41:23.746824619] Found a xfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-03:41:23.846219708] Checking for sar... [20081217-03:41:23.848714411] found [20081217-03:41:23.904598688] Checking for sar... [20081217-03:41:23.906702595] found [20081217-03:41:23.962808949] Checking for sar... [20081217-03:41:23.964960479] found [20081217-03:41:24.186647855] Checking for binutils-2.18 ... Already installed. [20081217-03:41:24.191082283] mv: cannot stat `lib64/*': No such file or directory [20081217-03:41:24.202535395] rmdir: lib64: No such file or directory [20081217-03:41:24.273608436] Checking for gettext-0.17 ... Already installed. [20081217-03:41:24.319937411] popt32-1.10.4 already installed. [20081217-03:41:24.335524802] popt64-1.10.4 already installed. [20081217-03:41:24.366450611] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-03:41:24.419160446] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-03:41:24.499183297] Daemon not running [20081217-03:41:24.518236641] Unloading oprofile module [20081217-03:41:24.753035874] Daemon not running [20081217-03:41:26.070930311] OPROFILE : using callgraph [5] [20081217-03:41:26.305012371] Daemon not running [20081217-03:41:26.306988136] Separate options: none [20081217-03:41:26.309037272] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-03:41:26.311238580] Image filter: none [20081217-03:41:26.313244253] Call-graph depth: 5 [20081217-03:41:26.392394460] FFSB version 6.0-RC2 started [20081217-03:41:26.394590477] [20081217-03:41:26.396456886] benchmark time = 300 [20081217-03:41:26.398527178] ThreadGroup 0 [20081217-03:41:26.400387298] ================ [20081217-03:41:26.402255579] num_threads = 1 [20081217-03:41:26.404006251] [20081217-03:41:26.405797358] read_random = off [20081217-03:41:26.407591034] read_size = 0 (0B) [20081217-03:41:26.409448766] read_blocksize = 0 (0B) [20081217-03:41:26.411190593] read_skip = off [20081217-03:41:26.412994278] read_skipsize = 0 (0B) [20081217-03:41:26.414764491] [20081217-03:41:26.416587162] write_random = on [20081217-03:41:26.418324623] write_size = 5242880 (5MB) [20081217-03:41:26.420286187] fsync_file = 0 [20081217-03:41:26.422189822] write_blocksize = 4096 (4KB) [20081217-03:41:26.423939592] wait time = 0 [20081217-03:41:26.425799392] [20081217-03:41:26.427617284] op weights [20081217-03:41:26.429353276] read = 0 (0.00%) [20081217-03:41:26.431183055] readall = 0 (0.00%) [20081217-03:41:26.432996587] write = 1 (100.00%) [20081217-03:41:26.434684094] create = 0 (0.00%) [20081217-03:41:26.436545979] append = 0 (0.00%) [20081217-03:41:26.438350223] delete = 0 (0.00%) [20081217-03:41:26.440102211] metaop = 0 (0.00%) [20081217-03:41:26.441951342] createdir = 0 (0.00%) [20081217-03:41:26.443764474] stat = 0 (0.00%) [20081217-03:41:26.445512116] writeall = 0 (0.00%) [20081217-03:41:26.447328192] writeall_fsync = 0 (0.00%) [20081217-03:41:26.449172251] open_close = 0 (0.00%) [20081217-03:41:26.450882722] write_fsync = 0 (0.00%) [20081217-03:41:26.452760030] create_fsync = 0 (0.00%) [20081217-03:41:26.454740695] append_fsync = 0 (0.00%) [20081217-03:41:26.456906334] [20081217-03:41:26.458892661] FileSystem /mnt/ffsb1 [20081217-03:41:26.460691277] ========== [20081217-03:41:26.462516268] num_dirs = 0 [20081217-03:41:26.464356575] starting files = 1024 [20081217-03:41:26.466240068] [20081217-03:41:26.468074720] min file size = 104857600 (100MB) [20081217-03:41:26.469830572] max file size = 104857600 (100MB) [20081217-03:41:26.471663492] directio = off [20081217-03:41:26.473441559] alignedio = on [20081217-03:41:26.475285135] bufferedio = off [20081217-03:41:26.477030033] [20081217-03:41:26.478882749] aging is off [20081217-03:41:26.480716814] current utilization = 4.47% [20081217-03:41:26.482459710] [20081217-03:41:26.484284740] checking existing fs: /mnt/ffsb1 [20081217-03:41:26.502310219] fs setup took 0 secs [20081217-03:41:27.405244341] Syncing()...0 sec [20081217-03:41:27.407335817] Starting Actual Benchmark At: Wed Dec 17 03:41:27 2008 [20081217-03:41:27.420081301] [20081217-03:46:34.417874494] Syncing()...5 sec [20081217-03:46:34.492276944] FFSB benchmark finished at: Wed Dec 17 03:46:34 2008 [20081217-03:46:34.495127777] [20081217-03:46:34.497978307] Results: [20081217-03:46:34.592441046] Benchmark took 306.69 sec [20081217-03:46:34.595177955] [20081217-03:46:34.597903647] Total Results [20081217-03:46:34.613406845] =============== [20081217-03:46:34.615760343] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-03:46:34.618492845] ======= ============ ========= ======= =========== ========== [20081217-03:46:34.620981142] write : 10068480 32829.37 100.000% 100.000% 2.5GB/sec [20081217-03:46:34.623371729] - [20081217-03:46:34.625888247] 32829.37 Transactions per Second [20081217-03:46:34.628255932] [20081217-03:46:34.630799445] Throughput Results [20081217-03:46:34.645927765] =================== [20081217-03:46:34.648306659] Write Throughput: 2.5GB/sec [20081217-03:46:34.650657845] [20081217-03:46:34.653138447] System Call Latency statistics in millisecs [20081217-03:46:34.655519780] ===== [20081217-03:46:34.657890600] Min Avg Max Total Calls [20081217-03:46:34.676470334] ======== ======== ======== ============ [20081217-03:46:34.678777115] [ open] 0.006000 0.159350 268.226013 7866 [20081217-03:46:34.680926109] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:46:34.683517278] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:46:34.686471498] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:46:34.688874735] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:46:34.692274197] msec_range[4] 200.000000 - 500.000000 : 2 [20081217-03:46:34.694771718] msec_range[5] 100.000000 - 200.000000 : 2 [20081217-03:46:34.698171705] msec_range[6] 50.000000 - 100.000000 : 2 [20081217-03:46:34.700925388] msec_range[7] 20.000000 - 50.000000 : 1 [20081217-03:46:34.704077552] msec_range[8] 10.000000 - 20.000000 : 1 [20081217-03:46:34.707868894] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-03:46:34.710297069] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-03:46:34.712685845] msec_range[11] 1.000000 - 2.000000 : 1 [20081217-03:46:34.714923947] msec_range[12] 0.500000 - 1.000000 : 2 [20081217-03:46:34.717389051] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-03:46:34.720347675] msec_range[14] 0.100000 - 0.200000 : 43 [20081217-03:46:34.723000021] msec_range[15] 0.050000 - 0.100000 : 1747 [20081217-03:46:34.725577816] msec_range[16] 0.020000 - 0.050000 : 3518 [20081217-03:46:34.727810835] msec_range[17] 0.010000 - 0.020000 : 1763 [20081217-03:46:34.730079555] msec_range[18] 0.000000 - 0.010000 : 784 [20081217-03:46:34.732413198] [20081217-03:46:34.734713042] [ write] 0.004000 0.026988 453.941010 10068480 [20081217-03:46:34.736838231] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:46:34.739130546] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:46:34.741389518] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:46:34.743784442] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:46:34.746130752] msec_range[4] 200.000000 - 500.000000 : 25 [20081217-03:46:34.748265429] msec_range[5] 100.000000 - 200.000000 : 151 [20081217-03:46:34.750674312] msec_range[6] 50.000000 - 100.000000 : 343 [20081217-03:46:34.752900502] msec_range[7] 20.000000 - 50.000000 : 1922 [20081217-03:46:34.755062365] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-03:46:34.757493298] msec_range[9] 5.000000 - 10.000000 : 4 [20081217-03:46:34.759876302] msec_range[10] 2.000000 - 5.000000 : 10 [20081217-03:46:34.762143263] msec_range[11] 1.000000 - 2.000000 : 735 [20081217-03:46:34.764367854] msec_range[12] 0.500000 - 1.000000 : 869 [20081217-03:46:34.766721228] msec_range[13] 0.200000 - 0.500000 : 288 [20081217-03:46:34.769161074] msec_range[14] 0.100000 - 0.200000 : 1631 [20081217-03:46:34.771664281] msec_range[15] 0.050000 - 0.100000 : 23361 [20081217-03:46:34.774016059] msec_range[16] 0.020000 - 0.050000 : 1975686 [20081217-03:46:34.776414291] msec_range[17] 0.010000 - 0.020000 : 5668298 [20081217-03:46:34.778861731] msec_range[18] 0.000000 - 0.010000 : 2395157 [20081217-03:46:34.781200399] [20081217-03:46:34.783532614] [ lseek] 0.000000 0.001278 4.700000 10068480 [20081217-03:46:34.785658222] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:46:34.787905160] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:46:34.790061421] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:46:34.792281397] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:46:34.794432500] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:46:34.796712011] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:46:34.798852581] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:46:34.801035880] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-03:46:34.803270711] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-03:46:34.805494169] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-03:46:34.807750794] msec_range[10] 2.000000 - 5.000000 : 1 [20081217-03:46:34.810100780] msec_range[11] 1.000000 - 2.000000 : 76 [20081217-03:46:34.812878791] msec_range[12] 0.500000 - 1.000000 : 78 [20081217-03:46:34.815384452] msec_range[13] 0.200000 - 0.500000 : 23 [20081217-03:46:34.818004694] msec_range[14] 0.100000 - 0.200000 : 33 [20081217-03:46:34.820300575] msec_range[15] 0.050000 - 0.100000 : 241 [20081217-03:46:34.822686162] msec_range[16] 0.020000 - 0.050000 : 2070 [20081217-03:46:34.824989048] msec_range[17] 0.010000 - 0.020000 : 5410 [20081217-03:46:34.827327494] msec_range[18] 0.000000 - 0.010000 : 10060548 [20081217-03:46:34.829503513] [20081217-03:46:34.831740083] [ close] 0.003000 0.008251 1.130000 7866 [20081217-03:46:34.833899382] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:46:34.836078704] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:46:34.838390714] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:46:34.840659606] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:46:34.843051593] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:46:34.845431214] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:46:34.847995074] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:46:34.850240146] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-03:46:34.852547993] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-03:46:34.854785333] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-03:46:34.858505684] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-03:46:34.860827513] msec_range[11] 1.000000 - 2.000000 : 1 [20081217-03:46:34.863043736] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-03:46:34.865156602] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-03:46:34.867482520] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-03:46:34.869649478] msec_range[15] 0.050000 - 0.100000 : 1 [20081217-03:46:34.871909741] msec_range[16] 0.020000 - 0.050000 : 44 [20081217-03:46:34.874086670] msec_range[17] 0.010000 - 0.020000 : 2319 [20081217-03:46:34.876289120] msec_range[18] 0.000000 - 0.010000 : 5501 [20081217-03:46:34.878424226] [20081217-03:46:34.880614952] [20081217-03:46:34.882740989] [20081217-03:46:34.884926881] [20081217-03:46:34.887109516] 8.0% User Time [20081217-03:46:34.889429680] 72.9% System Time [20081217-03:46:34.891615749] 81.0% CPU Utilization [20081217-03:46:34.893867578] Profilers reporting [20081217-03:47:00.568941246] Profilers postprocessing [20081217-03:47:01.706074235] Stopping profiling. [20081217-03:47:01.710810757] Killing daemon. [20081217-03:47:04.165659791] Processing File : /autobench/logs/ffsb.random_writes__threads_0001.08-12-17_03.41.14/analysis/oprofile.001 [20081217-03:47:04.167982221] Processing File : /autobench/logs/ffsb.random_writes__threads_0001.08-12-17_03.41.14/analysis/oprofile-brief.001 [20081217-03:47:04.615690336] Processing File : mpstat.001 [20081217-03:47:04.617808185] Discovered mpstat_interval=[5] [20081217-03:47:05.252001541] Processing Directory : sar.breakout.001 [20081217-03:47:05.254284251] Discovered sar_interval=[5] [20081217-03:47:05.572886419] Processing File : iostat.001 [20081217-03:47:05.575011247] Discovered iostat_interval=[5] [20081217-03:47:08.602128121] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0300/xfs-baseline' [20081217-03:47:13.519487265] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-03:47:15.693162130] PROCESSING COMMAND : 'mount -t xfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-03:47:15.957780994] PROCESSING COMMAND : 'run random_writes__threads_0016 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb num_threads=16' [20081217-03:47:16.001926540] new log requested [20081217-03:47:16.025891970] Running command ffsb [20081217-03:47:25.712203564] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb [20081217-03:47:25.730443391] Importing argument : num_threads=16 [20081217-03:47:25.756304280] Found a xfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-03:47:25.854970830] Checking for sar... [20081217-03:47:25.857301499] found [20081217-03:47:25.913595605] Checking for sar... [20081217-03:47:25.915697135] found [20081217-03:47:25.971425736] Checking for sar... [20081217-03:47:26.001033625] found [20081217-03:47:26.152788742] Checking for binutils-2.18 ... Already installed. [20081217-03:47:26.156968412] mv: cannot stat `lib64/*': No such file or directory [20081217-03:47:26.163806554] rmdir: lib64: No such file or directory [20081217-03:47:26.234972763] Checking for gettext-0.17 ... Already installed. [20081217-03:47:26.281530272] popt32-1.10.4 already installed. [20081217-03:47:26.296754809] popt64-1.10.4 already installed. [20081217-03:47:26.327490117] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-03:47:26.380421288] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-03:47:26.461074126] Daemon not running [20081217-03:47:26.479609480] Unloading oprofile module [20081217-03:47:26.703794032] Daemon not running [20081217-03:47:27.905569080] OPROFILE : using callgraph [5] [20081217-03:47:28.138920207] Daemon not running [20081217-03:47:28.141100103] Separate options: none [20081217-03:47:28.143161230] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-03:47:28.145313531] Image filter: none [20081217-03:47:28.147167435] Call-graph depth: 5 [20081217-03:47:28.227220517] FFSB version 6.0-RC2 started [20081217-03:47:28.229402806] [20081217-03:47:28.285932102] benchmark time = 300 [20081217-03:47:28.288230921] ThreadGroup 0 [20081217-03:47:28.290408152] ================ [20081217-03:47:28.292344973] num_threads = 16 [20081217-03:47:28.294512879] [20081217-03:47:28.296402508] read_random = off [20081217-03:47:28.298283406] read_size = 0 (0B) [20081217-03:47:28.300044783] read_blocksize = 0 (0B) [20081217-03:47:28.301871123] read_skip = off [20081217-03:47:28.303649438] read_skipsize = 0 (0B) [20081217-03:47:28.305457125] [20081217-03:47:28.307219055] write_random = on [20081217-03:47:28.309015995] write_size = 5242880 (5MB) [20081217-03:47:28.310783237] fsync_file = 0 [20081217-03:47:28.312751423] write_blocksize = 4096 (4KB) [20081217-03:47:28.314568153] wait time = 0 [20081217-03:47:28.316486138] [20081217-03:47:28.318315581] op weights [20081217-03:47:28.320085026] read = 0 (0.00%) [20081217-03:47:28.321931609] readall = 0 (0.00%) [20081217-03:47:28.323724325] write = 1 (100.00%) [20081217-03:47:28.325500203] create = 0 (0.00%) [20081217-03:47:28.327343347] append = 0 (0.00%) [20081217-03:47:28.329171510] delete = 0 (0.00%) [20081217-03:47:28.330897524] metaop = 0 (0.00%) [20081217-03:47:28.332677704] createdir = 0 (0.00%) [20081217-03:47:28.334518783] stat = 0 (0.00%) [20081217-03:47:28.336267040] writeall = 0 (0.00%) [20081217-03:47:28.338127369] writeall_fsync = 0 (0.00%) [20081217-03:47:28.339933034] open_close = 0 (0.00%) [20081217-03:47:28.341623917] write_fsync = 0 (0.00%) [20081217-03:47:28.343482648] create_fsync = 0 (0.00%) [20081217-03:47:28.345321359] append_fsync = 0 (0.00%) [20081217-03:47:28.347050907] [20081217-03:47:28.348880278] FileSystem /mnt/ffsb1 [20081217-03:47:28.350699672] ========== [20081217-03:47:28.352438573] num_dirs = 0 [20081217-03:47:28.354271121] starting files = 1024 [20081217-03:47:28.356087434] [20081217-03:47:28.357797890] min file size = 104857600 (100MB) [20081217-03:47:28.359645414] max file size = 104857600 (100MB) [20081217-03:47:28.361524010] directio = off [20081217-03:47:28.363242818] alignedio = on [20081217-03:47:28.365067926] bufferedio = off [20081217-03:47:28.367149696] [20081217-03:47:28.369018305] aging is off [20081217-03:47:28.370921905] current utilization = 4.47% [20081217-03:47:28.372785711] [20081217-03:47:28.464809763] checking existing fs: /mnt/ffsb1 [20081217-03:47:28.466649389] fs setup took 0 secs [20081217-03:47:29.210612988] Syncing()...0 sec [20081217-03:47:29.214480448] Starting Actual Benchmark At: Wed Dec 17 03:47:29 2008 [20081217-03:47:29.229205077] [20081217-03:52:37.598170122] Syncing()...6 sec [20081217-03:52:37.649150909] FFSB benchmark finished at: Wed Dec 17 03:52:37 2008 [20081217-03:52:37.652095057] [20081217-03:52:37.654659995] Results: [20081217-03:52:37.719151621] Benchmark took 308.08 sec [20081217-03:52:37.721679927] [20081217-03:52:37.724193525] Total Results [20081217-03:52:37.739335089] =============== [20081217-03:52:37.741264753] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-03:52:37.743647876] ======= ============ ========= ======= =========== ========== [20081217-03:52:37.745919563] write : 9411840 30549.99 100.000% 100.000% 2.33GB/sec [20081217-03:52:37.748028096] - [20081217-03:52:37.750458401] 30549.99 Transactions per Second [20081217-03:52:37.752734431] [20081217-03:52:37.755066865] Throughput Results [20081217-03:52:37.770042357] =================== [20081217-03:52:37.772056769] Write Throughput: 2.33GB/sec [20081217-03:52:37.774239527] [20081217-03:52:37.776649290] System Call Latency statistics in millisecs [20081217-03:52:37.778850208] ===== [20081217-03:52:37.781024926] Min Avg Max Total Calls [20081217-03:52:37.783494257] ======== ======== ======== ============ [20081217-03:52:37.785895887] [ open] 0.007000 0.095726 397.612000 7353 [20081217-03:52:37.787933810] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:52:37.789882584] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:52:37.792028298] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:52:37.794106516] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:52:37.796079000] msec_range[4] 200.000000 - 500.000000 : 1 [20081217-03:52:37.798002111] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:52:37.800143983] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:52:37.802223060] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-03:52:37.804171357] msec_range[8] 10.000000 - 20.000000 : 2 [20081217-03:52:37.806039052] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-03:52:37.808191648] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-03:52:37.810444958] msec_range[11] 1.000000 - 2.000000 : 4 [20081217-03:52:37.812473914] msec_range[12] 0.500000 - 1.000000 : 5 [20081217-03:52:37.814454650] msec_range[13] 0.200000 - 0.500000 : 5 [20081217-03:52:37.816798358] msec_range[14] 0.100000 - 0.200000 : 118 [20081217-03:52:37.818895712] msec_range[15] 0.050000 - 0.100000 : 1739 [20081217-03:52:37.820948127] msec_range[16] 0.020000 - 0.050000 : 3941 [20081217-03:52:37.822899475] msec_range[17] 0.010000 - 0.020000 : 1375 [20081217-03:52:37.825118971] msec_range[18] 0.000000 - 0.010000 : 163 [20081217-03:52:37.827245673] [20081217-03:52:37.829248836] [ write] 0.004000 0.502455 1932.593994 9411840 [20081217-03:52:37.831224180] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:52:37.833438308] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:52:37.835584865] msec_range[2] 1000.000000 - 2000.000000 : 1011 [20081217-03:52:37.837559786] msec_range[3] 500.000000 - 1000.000000 : 4173 [20081217-03:52:37.839513865] msec_range[4] 200.000000 - 500.000000 : 735 [20081217-03:52:37.841652047] msec_range[5] 100.000000 - 200.000000 : 96 [20081217-03:52:37.898759975] msec_range[6] 50.000000 - 100.000000 : 162 [20081217-03:52:37.901269021] msec_range[7] 20.000000 - 50.000000 : 194 [20081217-03:52:37.903249291] msec_range[8] 10.000000 - 20.000000 : 88 [20081217-03:52:37.905468120] msec_range[9] 5.000000 - 10.000000 : 143 [20081217-03:52:37.907764119] msec_range[10] 2.000000 - 5.000000 : 626 [20081217-03:52:37.909853714] msec_range[11] 1.000000 - 2.000000 : 2708 [20081217-03:52:37.911889832] msec_range[12] 0.500000 - 1.000000 : 4634 [20081217-03:52:37.914125003] msec_range[13] 0.200000 - 0.500000 : 3154 [20081217-03:52:37.916241899] msec_range[14] 0.100000 - 0.200000 : 5795 [20081217-03:52:37.918224952] msec_range[15] 0.050000 - 0.100000 : 55000 [20081217-03:52:37.920176309] msec_range[16] 0.020000 - 0.050000 : 2161126 [20081217-03:52:37.922345873] msec_range[17] 0.010000 - 0.020000 : 5605474 [20081217-03:52:37.924449204] msec_range[18] 0.000000 - 0.010000 : 1566721 [20081217-03:52:37.926416005] [20081217-03:52:37.928351090] [ lseek] 0.000000 0.007699 1463.911011 9411840 [20081217-03:52:37.930492039] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:52:37.932618970] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:52:37.934605828] msec_range[2] 1000.000000 - 2000.000000 : 7 [20081217-03:52:37.936633776] msec_range[3] 500.000000 - 1000.000000 : 41 [20081217-03:52:37.939093960] msec_range[4] 200.000000 - 500.000000 : 48 [20081217-03:52:37.942469124] msec_range[5] 100.000000 - 200.000000 : 20 [20081217-03:52:37.944756151] msec_range[6] 50.000000 - 100.000000 : 8 [20081217-03:52:37.947280571] msec_range[7] 20.000000 - 50.000000 : 9 [20081217-03:52:37.949752811] msec_range[8] 10.000000 - 20.000000 : 10 [20081217-03:52:37.951919393] msec_range[9] 5.000000 - 10.000000 : 23 [20081217-03:52:37.953868663] msec_range[10] 2.000000 - 5.000000 : 50 [20081217-03:52:37.956031481] msec_range[11] 1.000000 - 2.000000 : 153 [20081217-03:52:37.958275868] msec_range[12] 0.500000 - 1.000000 : 346 [20081217-03:52:37.960318548] msec_range[13] 0.200000 - 0.500000 : 603 [20081217-03:52:37.962253982] msec_range[14] 0.100000 - 0.200000 : 1383 [20081217-03:52:37.964467793] msec_range[15] 0.050000 - 0.100000 : 3985 [20081217-03:52:37.966577413] msec_range[16] 0.020000 - 0.050000 : 12835 [20081217-03:52:37.968545697] msec_range[17] 0.010000 - 0.020000 : 19075 [20081217-03:52:37.970500242] msec_range[18] 0.000000 - 0.010000 : 9373244 [20081217-03:52:37.972640266] [20081217-03:52:37.975047681] [ close] 0.003000 0.010375 2.087000 7353 [20081217-03:52:37.977108043] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:52:37.979131672] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:52:37.981322584] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:52:37.983433250] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:52:37.985409493] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:52:37.987333423] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:52:37.989706502] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:52:37.993284247] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-03:52:37.995473321] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-03:52:37.998013907] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-03:52:38.000342654] msec_range[10] 2.000000 - 5.000000 : 1 [20081217-03:52:38.002448599] msec_range[11] 1.000000 - 2.000000 : 1 [20081217-03:52:38.004539250] msec_range[12] 0.500000 - 1.000000 : 2 [20081217-03:52:38.007055877] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-03:52:38.009540663] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-03:52:38.011834088] msec_range[15] 0.050000 - 0.100000 : 4 [20081217-03:52:38.014111442] msec_range[16] 0.020000 - 0.050000 : 114 [20081217-03:52:38.016363478] msec_range[17] 0.010000 - 0.020000 : 3167 [20081217-03:52:38.018967051] msec_range[18] 0.000000 - 0.010000 : 4064 [20081217-03:52:38.021102694] [20081217-03:52:38.023049459] [20081217-03:52:38.025199532] [20081217-03:52:38.027422943] [20081217-03:52:38.029338060] 7.9% User Time [20081217-03:52:38.031526624] 149.1% System Time [20081217-03:52:38.033750323] 157.0% CPU Utilization [20081217-03:52:38.036037962] Profilers reporting [20081217-03:52:55.796061202] Profilers postprocessing [20081217-03:52:56.936728612] Stopping profiling. [20081217-03:52:56.941173010] Killing daemon. [20081217-03:52:59.392199314] Processing File : /autobench/logs/ffsb.random_writes__threads_0016.08-12-17_03.47.16/analysis/oprofile.001 [20081217-03:52:59.394446754] Processing File : /autobench/logs/ffsb.random_writes__threads_0016.08-12-17_03.47.16/analysis/oprofile-brief.001 [20081217-03:52:59.639132911] Processing File : mpstat.001 [20081217-03:52:59.641295269] Discovered mpstat_interval=[5] [20081217-03:53:00.269728675] Processing Directory : sar.breakout.001 [20081217-03:53:00.271988744] Discovered sar_interval=[5] [20081217-03:53:00.614213666] Processing File : iostat.001 [20081217-03:53:00.616370356] Discovered iostat_interval=[5] [20081217-03:53:02.622764678] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0300/xfs-baseline' [20081217-03:53:07.781530527] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-03:53:10.165965223] PROCESSING COMMAND : 'mount -t xfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-03:53:10.433198351] PROCESSING COMMAND : 'run random_writes__threads_0128 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb num_threads=128' [20081217-03:53:10.477939291] new log requested [20081217-03:53:10.501602393] Running command ffsb [20081217-03:53:19.945076673] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes.ffsb [20081217-03:53:19.961136851] Importing argument : num_threads=128 [20081217-03:53:19.987707161] Found a xfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-03:53:20.083574163] Checking for sar... [20081217-03:53:20.085768514] found [20081217-03:53:20.141932609] Checking for sar... [20081217-03:53:20.144189455] found [20081217-03:53:20.199916038] Checking for sar... [20081217-03:53:20.202034813] found [20081217-03:53:20.362999787] Checking for binutils-2.18 ... Already installed. [20081217-03:53:20.367469368] mv: cannot stat `lib64/*': No such file or directory [20081217-03:53:20.380034556] rmdir: lib64: No such file or directory [20081217-03:53:20.451203651] Checking for gettext-0.17 ... Already installed. [20081217-03:53:20.521522520] popt32-1.10.4 already installed. [20081217-03:53:20.550610929] popt64-1.10.4 already installed. [20081217-03:53:20.581349175] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-03:53:20.634981479] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-03:53:20.714073579] Daemon not running [20081217-03:53:20.737827209] Unloading oprofile module [20081217-03:53:20.966207871] Daemon not running [20081217-03:53:21.757925811] OPROFILE : using callgraph [5] [20081217-03:53:21.990947732] Daemon not running [20081217-03:53:21.993037891] Separate options: none [20081217-03:53:21.995095012] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-03:53:21.997207169] Image filter: none [20081217-03:53:21.999304620] Call-graph depth: 5 [20081217-03:53:22.079441755] FFSB version 6.0-RC2 started [20081217-03:53:22.081450441] [20081217-03:53:22.570566054] benchmark time = 300 [20081217-03:53:22.572477270] ThreadGroup 0 [20081217-03:53:22.574756444] ================ [20081217-03:53:22.576656637] num_threads = 128 [20081217-03:53:22.578526599] [20081217-03:53:22.580319551] read_random = off [20081217-03:53:22.582232114] read_size = 0 (0B) [20081217-03:53:22.584039481] read_blocksize = 0 (0B) [20081217-03:53:22.585906050] read_skip = off [20081217-03:53:22.587688727] read_skipsize = 0 (0B) [20081217-03:53:22.589575012] [20081217-03:53:22.591334649] write_random = on [20081217-03:53:22.593153352] write_size = 5242880 (5MB) [20081217-03:53:22.594888653] fsync_file = 0 [20081217-03:53:22.597181485] write_blocksize = 4096 (4KB) [20081217-03:53:22.599163070] wait time = 0 [20081217-03:53:22.600973049] [20081217-03:53:22.602745253] op weights [20081217-03:53:22.604782208] read = 0 (0.00%) [20081217-03:53:22.606876268] readall = 0 (0.00%) [20081217-03:53:22.609087720] write = 1 (100.00%) [20081217-03:53:22.611034758] create = 0 (0.00%) [20081217-03:53:22.612840950] append = 0 (0.00%) [20081217-03:53:22.614735668] delete = 0 (0.00%) [20081217-03:53:22.616600923] metaop = 0 (0.00%) [20081217-03:53:22.618330432] createdir = 0 (0.00%) [20081217-03:53:22.620207805] stat = 0 (0.00%) [20081217-03:53:22.622066924] writeall = 0 (0.00%) [20081217-03:53:22.623844334] writeall_fsync = 0 (0.00%) [20081217-03:53:22.625687317] open_close = 0 (0.00%) [20081217-03:53:22.627532919] write_fsync = 0 (0.00%) [20081217-03:53:22.629284757] create_fsync = 0 (0.00%) [20081217-03:53:22.631135102] append_fsync = 0 (0.00%) [20081217-03:53:22.632982785] [20081217-03:53:22.634733160] FileSystem /mnt/ffsb1 [20081217-03:53:22.636567332] ========== [20081217-03:53:22.638400983] num_dirs = 0 [20081217-03:53:22.640157908] starting files = 1024 [20081217-03:53:22.641986907] [20081217-03:53:22.643848340] min file size = 104857600 (100MB) [20081217-03:53:22.645585810] max file size = 104857600 (100MB) [20081217-03:53:22.647372711] directio = off [20081217-03:53:22.649460722] alignedio = on [20081217-03:53:22.651357403] bufferedio = off [20081217-03:53:22.653434362] [20081217-03:53:22.655273624] aging is off [20081217-03:53:22.657234759] current utilization = 4.47% [20081217-03:53:22.659148461] [20081217-03:53:22.660988893] checking existing fs: /mnt/ffsb1 [20081217-03:53:22.662759001] fs setup took 0 secs [20081217-03:53:23.168370055] Syncing()...0 sec [20081217-03:53:23.173898720] Starting Actual Benchmark At: Wed Dec 17 03:53:23 2008 [20081217-03:53:23.188941445] [20081217-03:58:34.166538962] Syncing()...5 sec [20081217-03:58:34.211607523] FFSB benchmark finished at: Wed Dec 17 03:58:33 2008 [20081217-03:58:34.214502622] [20081217-03:58:34.217187056] Results: [20081217-03:58:34.263775203] Benchmark took 310.70 sec [20081217-03:58:34.266331169] [20081217-03:58:34.268663250] Total Results [20081217-03:58:34.283533941] =============== [20081217-03:58:34.285633991] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-03:58:34.288098891] ======= ============ ========= ======= =========== ========== [20081217-03:58:34.290399340] write : 6036480 19428.90 100.000% 100.000% 1.48GB/sec [20081217-03:58:34.292493003] - [20081217-03:58:34.294884923] 19428.90 Transactions per Second [20081217-03:58:34.297273850] [20081217-03:58:34.299363192] Throughput Results [20081217-03:58:34.313480601] =================== [20081217-03:58:34.315864177] Write Throughput: 1.48GB/sec [20081217-03:58:34.317685651] [20081217-03:58:34.319964557] System Call Latency statistics in millisecs [20081217-03:58:34.322394420] ===== [20081217-03:58:34.324497004] Min Avg Max Total Calls [20081217-03:58:34.326649458] ======== ======== ======== ============ [20081217-03:58:34.329138101] [ open] 0.007000 0.123371 214.507004 4716 [20081217-03:58:34.331532613] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:58:34.333676592] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:58:34.335655302] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:58:34.347258680] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:58:34.349452317] msec_range[4] 200.000000 - 500.000000 : 1 [20081217-03:58:34.351514398] msec_range[5] 100.000000 - 200.000000 : 1 [20081217-03:58:34.353544728] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:58:34.355594049] msec_range[7] 20.000000 - 50.000000 : 1 [20081217-03:58:34.357770824] msec_range[8] 10.000000 - 20.000000 : 1 [20081217-03:58:34.359838107] msec_range[9] 5.000000 - 10.000000 : 2 [20081217-03:58:34.361758008] msec_range[10] 2.000000 - 5.000000 : 1 [20081217-03:58:34.363793654] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-03:58:34.365981848] msec_range[12] 0.500000 - 1.000000 : 9 [20081217-03:58:34.368057925] msec_range[13] 0.200000 - 0.500000 : 10 [20081217-03:58:34.370005752] msec_range[14] 0.100000 - 0.200000 : 171 [20081217-03:58:34.372435547] msec_range[15] 0.050000 - 0.100000 : 1234 [20081217-03:58:34.374588060] msec_range[16] 0.020000 - 0.050000 : 2608 [20081217-03:58:34.376651201] msec_range[17] 0.010000 - 0.020000 : 619 [20081217-03:58:34.378609074] msec_range[18] 0.000000 - 0.010000 : 58 [20081217-03:58:34.380622557] [20081217-03:58:34.382874951] [ write] 0.004000 5.896006 25601.419922 6036480 [20081217-03:58:34.384947246] msec_range[0] 5000.000000 - 10000.000000 : 2522 [20081217-03:58:34.386943820] msec_range[1] 2000.000000 - 5000.000000 : 2158 [20081217-03:58:34.388973846] msec_range[2] 1000.000000 - 2000.000000 : 664 [20081217-03:58:34.391240420] msec_range[3] 500.000000 - 1000.000000 : 62 [20081217-03:58:34.393270032] msec_range[4] 200.000000 - 500.000000 : 308 [20081217-03:58:34.395291184] msec_range[5] 100.000000 - 200.000000 : 274 [20081217-03:58:34.397280522] msec_range[6] 50.000000 - 100.000000 : 205 [20081217-03:58:34.399423581] msec_range[7] 20.000000 - 50.000000 : 105 [20081217-03:58:34.401461891] msec_range[8] 10.000000 - 20.000000 : 99 [20081217-03:58:34.403432574] msec_range[9] 5.000000 - 10.000000 : 277 [20081217-03:58:34.405426083] msec_range[10] 2.000000 - 5.000000 : 1263 [20081217-03:58:34.407590805] msec_range[11] 1.000000 - 2.000000 : 3388 [20081217-03:58:34.409624075] msec_range[12] 0.500000 - 1.000000 : 5404 [20081217-03:58:34.411555480] msec_range[13] 0.200000 - 0.500000 : 8771 [20081217-03:58:34.413514548] msec_range[14] 0.100000 - 0.200000 : 25213 [20081217-03:58:34.415653202] msec_range[15] 0.050000 - 0.100000 : 113374 [20081217-03:58:34.417742823] msec_range[16] 0.020000 - 0.050000 : 1657237 [20081217-03:58:34.419680482] msec_range[17] 0.010000 - 0.020000 : 3386285 [20081217-03:58:34.421652511] msec_range[18] 0.000000 - 0.010000 : 828169 [20081217-03:58:34.423856704] [20081217-03:58:34.425914135] [ lseek] 0.000000 0.532153 19165.492188 6036480 [20081217-03:58:34.428007826] msec_range[0] 5000.000000 - 10000.000000 : 225 [20081217-03:58:34.430323881] msec_range[1] 2000.000000 - 5000.000000 : 245 [20081217-03:58:34.433131552] msec_range[2] 1000.000000 - 2000.000000 : 112 [20081217-03:58:34.435354556] msec_range[3] 500.000000 - 1000.000000 : 38 [20081217-03:58:34.437280018] msec_range[4] 200.000000 - 500.000000 : 37 [20081217-03:58:34.439587082] msec_range[5] 100.000000 - 200.000000 : 31 [20081217-03:58:34.441723262] msec_range[6] 50.000000 - 100.000000 : 19 [20081217-03:58:34.443849726] msec_range[7] 20.000000 - 50.000000 : 20 [20081217-03:58:34.445761547] msec_range[8] 10.000000 - 20.000000 : 18 [20081217-03:58:34.447937200] msec_range[9] 5.000000 - 10.000000 : 92 [20081217-03:58:34.450197413] msec_range[10] 2.000000 - 5.000000 : 288 [20081217-03:58:34.452296285] msec_range[11] 1.000000 - 2.000000 : 410 [20081217-03:58:34.454550800] msec_range[12] 0.500000 - 1.000000 : 698 [20081217-03:58:34.456774816] msec_range[13] 0.200000 - 0.500000 : 2520 [20081217-03:58:34.458796092] msec_range[14] 0.100000 - 0.200000 : 6658 [20081217-03:58:34.460618110] msec_range[15] 0.050000 - 0.100000 : 17419 [20081217-03:58:34.464645789] msec_range[16] 0.020000 - 0.050000 : 45218 [20081217-03:58:34.468613559] msec_range[17] 0.010000 - 0.020000 : 39791 [20081217-03:58:34.471086137] msec_range[18] 0.000000 - 0.010000 : 5922596 [20081217-03:58:34.473988803] [20081217-03:58:34.476158916] [ close] 0.003000 0.010952 0.147000 4716 [20081217-03:58:34.478677150] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-03:58:34.480920488] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-03:58:34.483102782] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-03:58:34.485212904] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-03:58:34.487529460] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-03:58:34.489543741] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-03:58:34.491952698] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-03:58:34.494011480] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-03:58:34.496252814] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-03:58:34.498321776] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-03:58:34.500397876] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-03:58:34.502456899] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-03:58:34.504635380] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-03:58:34.506722566] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-03:58:34.508711895] msec_range[14] 0.100000 - 0.200000 : 2 [20081217-03:58:34.510696962] msec_range[15] 0.050000 - 0.100000 : 13 [20081217-03:58:34.512871597] msec_range[16] 0.020000 - 0.050000 : 183 [20081217-03:58:34.514972520] msec_range[17] 0.010000 - 0.020000 : 2296 [20081217-03:58:34.517698038] msec_range[18] 0.000000 - 0.010000 : 2222 [20081217-03:58:34.520151237] [20081217-03:58:34.522936505] [20081217-03:58:34.525431466] [20081217-03:58:34.527912609] [20081217-03:58:34.530128591] 4.9% User Time [20081217-03:58:34.532230568] 115.9% System Time [20081217-03:58:34.534259100] 120.7% CPU Utilization [20081217-03:58:34.549809063] Profilers reporting [20081217-03:58:51.856072344] Profilers postprocessing [20081217-03:58:52.993348250] Stopping profiling. [20081217-03:58:52.997735860] Killing daemon. [20081217-03:58:55.449860982] Processing File : /autobench/logs/ffsb.random_writes__threads_0128.08-12-17_03.53.10/analysis/oprofile.001 [20081217-03:58:55.452063348] Processing File : /autobench/logs/ffsb.random_writes__threads_0128.08-12-17_03.53.10/analysis/oprofile-brief.001 [20081217-03:58:55.711212615] Processing File : mpstat.001 [20081217-03:58:55.713275567] Discovered mpstat_interval=[5] [20081217-03:58:56.321284827] Processing Directory : sar.breakout.001 [20081217-03:58:56.323554787] Discovered sar_interval=[5] [20081217-03:58:56.662383213] Processing File : iostat.001 [20081217-03:58:56.664565666] Discovered iostat_interval=[5] [20081217-03:58:58.712800563] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0300/xfs-baseline' [20081217-03:59:03.369665264] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-03:59:05.781540013] PROCESSING COMMAND : 'mount -t xfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-03:59:06.045888070] PROCESSING COMMAND : 'run random_writes_odirect__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb num_threads=1' [20081217-03:59:06.090913501] new log requested [20081217-03:59:06.115085821] Running command ffsb [20081217-03:59:15.432803350] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb [20081217-03:59:15.448951005] Importing argument : num_threads=1 [20081217-03:59:15.475932508] Found a xfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-03:59:15.575295959] Checking for sar... [20081217-03:59:15.577469502] found [20081217-03:59:15.633705170] Checking for sar... [20081217-03:59:15.635966001] found [20081217-03:59:15.691766312] Checking for sar... [20081217-03:59:15.693980282] found [20081217-03:59:15.854787406] Checking for binutils-2.18 ... Already installed. [20081217-03:59:15.859094509] mv: cannot stat `lib64/*': No such file or directory [20081217-03:59:15.872071650] rmdir: lib64: No such file or directory [20081217-03:59:15.943223126] Checking for gettext-0.17 ... Already installed. [20081217-03:59:15.989971254] popt32-1.10.4 already installed. [20081217-03:59:16.006155267] popt64-1.10.4 already installed. [20081217-03:59:16.036673108] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-03:59:16.109855518] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-03:59:16.191309429] Daemon not running [20081217-03:59:16.217782011] Unloading oprofile module [20081217-03:59:16.418017012] Daemon not running [20081217-03:59:17.166547222] OPROFILE : using callgraph [5] [20081217-03:59:17.399414529] Daemon not running [20081217-03:59:17.401503119] Separate options: none [20081217-03:59:17.403558968] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-03:59:17.405702643] Image filter: none [20081217-03:59:17.407837175] Call-graph depth: 5 [20081217-03:59:17.487295772] FFSB version 6.0-RC2 started [20081217-03:59:17.489454676] [20081217-03:59:17.491601119] benchmark time = 300 [20081217-03:59:17.493751285] ThreadGroup 0 [20081217-03:59:17.495657966] ================ [20081217-03:59:17.497500385] num_threads = 1 [20081217-03:59:17.499275180] [20081217-03:59:17.501120398] read_random = off [20081217-03:59:17.503132046] read_size = 0 (0B) [20081217-03:59:17.505223723] read_blocksize = 0 (0B) [20081217-03:59:17.507096058] read_skip = off [20081217-03:59:17.508996211] read_skipsize = 0 (0B) [20081217-03:59:17.510888651] [20081217-03:59:17.512767433] write_random = on [20081217-03:59:17.514545357] write_size = 5242880 (5MB) [20081217-03:59:17.516404493] fsync_file = 0 [20081217-03:59:17.518241661] write_blocksize = 4096 (4KB) [20081217-03:59:17.519957815] wait time = 0 [20081217-03:59:17.521835643] [20081217-03:59:17.523652093] op weights [20081217-03:59:17.525416174] read = 0 (0.00%) [20081217-03:59:17.527244426] readall = 0 (0.00%) [20081217-03:59:17.529064322] write = 1 (100.00%) [20081217-03:59:17.530877826] create = 0 (0.00%) [20081217-03:59:17.532737284] append = 0 (0.00%) [20081217-03:59:17.534584327] delete = 0 (0.00%) [20081217-03:59:17.536362974] metaop = 0 (0.00%) [20081217-03:59:17.538224439] createdir = 0 (0.00%) [20081217-03:59:17.540005470] stat = 0 (0.00%) [20081217-03:59:17.541776754] writeall = 0 (0.00%) [20081217-03:59:17.543616515] writeall_fsync = 0 (0.00%) [20081217-03:59:17.545465492] open_close = 0 (0.00%) [20081217-03:59:17.547212358] write_fsync = 0 (0.00%) [20081217-03:59:17.549099213] create_fsync = 0 (0.00%) [20081217-03:59:17.550941800] append_fsync = 0 (0.00%) [20081217-03:59:17.552694028] [20081217-03:59:17.554536066] FileSystem /mnt/ffsb1 [20081217-03:59:17.556356177] ========== [20081217-03:59:17.558123322] num_dirs = 0 [20081217-03:59:17.559963055] starting files = 1024 [20081217-03:59:17.562088463] [20081217-03:59:17.564031245] min file size = 104857600 (100MB) [20081217-03:59:17.575165532] max file size = 104857600 (100MB) [20081217-03:59:17.577228924] directio = on [20081217-03:59:17.579106438] alignedio = on [20081217-03:59:17.581107271] bufferedio = off [20081217-03:59:17.583005196] [20081217-03:59:17.584942354] aging is off [20081217-03:59:17.586729908] current utilization = 4.47% [20081217-03:59:17.599390966] [20081217-03:59:17.601240717] checking existing fs: /mnt/ffsb1 [20081217-03:59:17.603057030] fs setup took 0 secs [20081217-03:59:18.074545513] Syncing()...0 sec [20081217-03:59:18.076605033] Starting Actual Benchmark At: Wed Dec 17 03:59:18 2008 [20081217-03:59:18.089449850] [20081217-04:04:21.115249135] Syncing()...1 sec [20081217-04:04:21.118160177] FFSB benchmark finished at: Wed Dec 17 04:04:21 2008 [20081217-04:04:21.120733839] [20081217-04:04:21.123096096] Results: [20081217-04:04:21.138543520] Benchmark took 303.04 sec [20081217-04:04:21.141114706] [20081217-04:04:21.143783801] Total Results [20081217-04:04:21.159271464] =============== [20081217-04:04:21.161488144] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-04:04:21.163715027] ======= ============ ========= ======= =========== ========== [20081217-04:04:21.166311554] write : 861440 2842.66 100.000% 100.000% 222MB/sec [20081217-04:04:21.168866510] - [20081217-04:04:21.171345661] 2842.66 Transactions per Second [20081217-04:04:21.174020566] [20081217-04:04:21.176560330] Throughput Results [20081217-04:04:21.191955650] =================== [20081217-04:04:21.194491707] Write Throughput: 222MB/sec [20081217-04:04:21.196677838] [20081217-04:04:21.198831058] System Call Latency statistics in millisecs [20081217-04:04:21.200910013] ===== [20081217-04:04:21.203248710] Min Avg Max Total Calls [20081217-04:04:21.207054959] ======== ======== ======== ============ [20081217-04:04:21.210135582] [ open] 0.008000 0.015250 0.036000 673 [20081217-04:04:21.212959524] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-04:04:21.215890646] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-04:04:21.218760573] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-04:04:21.221493304] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-04:04:21.226819170] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-04:04:21.229420123] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-04:04:21.231833732] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-04:04:21.234465417] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-04:04:21.237515808] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-04:04:21.240733749] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-04:04:21.244073505] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-04:04:21.246703192] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-04:04:21.249598044] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-04:04:21.252342951] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-04:04:21.254936829] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-04:04:21.257617008] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-04:04:21.259909938] msec_range[16] 0.020000 - 0.050000 : 135 [20081217-04:04:21.262187993] msec_range[17] 0.010000 - 0.020000 : 508 [20081217-04:04:21.264848150] msec_range[18] 0.000000 - 0.010000 : 30 [20081217-04:04:21.267835069] [20081217-04:04:21.270661634] [ write] 0.191000 0.346530 262.912994 861440 [20081217-04:04:21.273005816] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-04:04:21.276762260] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-04:04:21.279451865] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-04:04:21.282159901] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-04:04:21.284607194] msec_range[4] 200.000000 - 500.000000 : 42 [20081217-04:04:21.287176659] msec_range[5] 100.000000 - 200.000000 : 441 [20081217-04:04:21.290146017] msec_range[6] 50.000000 - 100.000000 : 152 [20081217-04:04:21.292541529] msec_range[7] 20.000000 - 50.000000 : 272 [20081217-04:04:21.295131940] msec_range[8] 10.000000 - 20.000000 : 152 [20081217-04:04:21.297512635] msec_range[9] 5.000000 - 10.000000 : 118 [20081217-04:04:21.300293807] msec_range[10] 2.000000 - 5.000000 : 136 [20081217-04:04:21.302590864] msec_range[11] 1.000000 - 2.000000 : 2640 [20081217-04:04:21.304828391] msec_range[12] 0.500000 - 1.000000 : 1311 [20081217-04:04:21.307416184] msec_range[13] 0.200000 - 0.500000 : 851479 [20081217-04:04:21.309215261] msec_range[14] 0.100000 - 0.200000 : 4697 [20081217-04:04:21.311152020] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-04:04:21.313530547] msec_range[16] 0.020000 - 0.050000 : 0 [20081217-04:04:21.316241091] msec_range[17] 0.010000 - 0.020000 : 0 [20081217-04:04:21.319058716] msec_range[18] 0.000000 - 0.010000 : 0 [20081217-04:04:21.321741301] [20081217-04:04:21.324427294] [ lseek] 0.000000 0.001420 0.279000 861440 [20081217-04:04:21.331101061] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-04:04:21.333630690] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-04:04:21.336161267] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-04:04:21.338707702] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-04:04:21.341399720] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-04:04:21.343931321] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-04:04:21.346427514] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-04:04:21.349806149] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-04:04:21.353149793] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-04:04:21.355797990] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-04:04:21.358287098] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-04:04:21.360658324] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-04:04:21.362704643] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-04:04:21.366033880] msec_range[13] 0.200000 - 0.500000 : 3 [20081217-04:04:21.369067236] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-04:04:21.371801816] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-04:04:21.374510960] msec_range[16] 0.020000 - 0.050000 : 11 [20081217-04:04:21.377134009] msec_range[17] 0.010000 - 0.020000 : 337 [20081217-04:04:21.379412604] msec_range[18] 0.000000 - 0.010000 : 861089 [20081217-04:04:21.381591539] [20081217-04:04:21.383515715] [ close] 0.004000 0.007000 0.021000 673 [20081217-04:04:21.385658489] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-04:04:21.388257306] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-04:04:21.390912334] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-04:04:21.393494587] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-04:04:21.395808504] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-04:04:21.398481808] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-04:04:21.404977198] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-04:04:21.407522590] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-04:04:21.409973100] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-04:04:21.412247319] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-04:04:21.414948716] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-04:04:21.418462516] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-04:04:21.421627813] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-04:04:21.424331543] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-04:04:21.426745920] msec_range[14] 0.100000 - 0.200000 : 0 [20081217-04:04:21.429022202] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-04:04:21.431490060] msec_range[16] 0.020000 - 0.050000 : 1 [20081217-04:04:21.434083445] msec_range[17] 0.010000 - 0.020000 : 97 [20081217-04:04:21.436148091] msec_range[18] 0.000000 - 0.010000 : 575 [20081217-04:04:21.438421961] [20081217-04:04:21.440797488] [20081217-04:04:21.442925439] [20081217-04:04:21.445100917] [20081217-04:04:21.447379492] 0.9% User Time [20081217-04:04:21.449663516] 10.4% System Time [20081217-04:04:21.452024229] 11.3% CPU Utilization [20081217-04:04:21.454235459] Profilers reporting [20081217-04:04:38.286896440] Profilers postprocessing [20081217-04:04:39.423929189] Stopping profiling. [20081217-04:04:39.428271196] Killing daemon. [20081217-04:04:40.604976627] Processing File : /autobench/logs/ffsb.random_writes_odirect__threads_0001.08-12-17_03.59.06/analysis/oprofile.001 [20081217-04:04:40.607157908] Processing File : /autobench/logs/ffsb.random_writes_odirect__threads_0001.08-12-17_03.59.06/analysis/oprofile-brief.001 [20081217-04:04:40.722135623] Processing File : mpstat.001 [20081217-04:04:40.724422309] Discovered mpstat_interval=[5] [20081217-04:04:41.276578940] Processing Directory : sar.breakout.001 [20081217-04:04:41.278820317] Discovered sar_interval=[5] [20081217-04:04:41.462480807] Processing File : iostat.001 [20081217-04:04:41.464787282] Discovered iostat_interval=[5] [20081217-04:04:43.321166853] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0300/xfs-baseline' [20081217-04:04:47.824960143] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-04:04:47.961287891] PROCESSING COMMAND : 'mount -t xfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-04:04:48.217971651] PROCESSING COMMAND : 'run random_writes_odirect__threads_0016 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb num_threads=16' [20081217-04:04:48.262549438] new log requested [20081217-04:04:48.287084597] Running command ffsb [20081217-04:04:56.456869937] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb [20081217-04:04:56.476750752] Importing argument : num_threads=16 [20081217-04:04:56.503475999] Found a xfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-04:04:56.591748945] Checking for sar... [20081217-04:04:56.593811602] found [20081217-04:04:56.650661869] Checking for sar... [20081217-04:04:56.652786143] found [20081217-04:04:56.708533714] Checking for sar... [20081217-04:04:56.710814838] found [20081217-04:04:56.840711948] Checking for binutils-2.18 ... Already installed. [20081217-04:04:56.845217125] mv: cannot stat `lib64/*': No such file or directory [20081217-04:04:56.847922206] rmdir: lib64: No such file or directory [20081217-04:04:56.908671562] Checking for gettext-0.17 ... Already installed. [20081217-04:04:56.949739263] popt32-1.10.4 already installed. [20081217-04:04:56.965897291] popt64-1.10.4 already installed. [20081217-04:04:56.996820638] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-04:04:57.049666963] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-04:04:57.130663834] Daemon not running [20081217-04:04:57.141581979] Unloading oprofile module [20081217-04:04:57.249773767] Daemon not running [20081217-04:04:58.352330517] OPROFILE : using callgraph [5] [20081217-04:04:58.586865519] Daemon not running [20081217-04:04:58.589071107] Separate options: none [20081217-04:04:58.591120383] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-04:04:58.593246578] Image filter: none [20081217-04:04:58.595107827] Call-graph depth: 5 [20081217-04:04:58.654381782] FFSB version 6.0-RC2 started [20081217-04:04:58.656556849] [20081217-04:04:58.715465937] benchmark time = 300 [20081217-04:04:58.717568921] ThreadGroup 0 [20081217-04:04:58.719707279] ================ [20081217-04:04:58.721870329] num_threads = 16 [20081217-04:04:58.723853421] [20081217-04:04:58.725913963] read_random = off [20081217-04:04:58.727757356] read_size = 0 (0B) [20081217-04:04:58.729651754] read_blocksize = 0 (0B) [20081217-04:04:58.731547058] read_skip = off [20081217-04:04:58.733362113] read_skipsize = 0 (0B) [20081217-04:04:58.735260012] [20081217-04:04:58.737118803] write_random = on [20081217-04:04:58.738882068] write_size = 5242880 (5MB) [20081217-04:04:58.740802796] fsync_file = 0 [20081217-04:04:58.742590611] write_blocksize = 4096 (4KB) [20081217-04:04:58.744502371] wait time = 0 [20081217-04:04:58.746360953] [20081217-04:04:58.748078837] op weights [20081217-04:04:58.749951292] read = 0 (0.00%) [20081217-04:04:58.751823369] readall = 0 (0.00%) [20081217-04:04:58.753559506] write = 1 (100.00%) [20081217-04:04:58.755397495] create = 0 (0.00%) [20081217-04:04:58.757244306] append = 0 (0.00%) [20081217-04:04:58.758981092] delete = 0 (0.00%) [20081217-04:04:58.760853833] metaop = 0 (0.00%) [20081217-04:04:58.762702856] createdir = 0 (0.00%) [20081217-04:04:58.764471072] stat = 0 (0.00%) [20081217-04:04:58.766316998] writeall = 0 (0.00%) [20081217-04:04:58.768113432] writeall_fsync = 0 (0.00%) [20081217-04:04:58.770008935] open_close = 0 (0.00%) [20081217-04:04:58.771831762] write_fsync = 0 (0.00%) [20081217-04:04:58.773767967] create_fsync = 0 (0.00%) [20081217-04:04:58.775545140] append_fsync = 0 (0.00%) [20081217-04:04:58.777446465] [20081217-04:04:58.779356465] FileSystem /mnt/ffsb1 [20081217-04:04:58.781069499] ========== [20081217-04:04:58.782948240] num_dirs = 0 [20081217-04:04:58.784806901] starting files = 1024 [20081217-04:04:58.786561969] [20081217-04:04:58.788401811] min file size = 104857600 (100MB) [20081217-04:04:58.790267521] max file size = 104857600 (100MB) [20081217-04:04:58.791955304] directio = on [20081217-04:04:58.794035533] alignedio = on [20081217-04:04:58.795909437] bufferedio = off [20081217-04:04:58.797765059] [20081217-04:04:58.799641172] aging is off [20081217-04:04:58.801507305] current utilization = 4.47% [20081217-04:04:58.803379780] [20081217-04:04:58.805245785] checking existing fs: /mnt/ffsb1 [20081217-04:04:58.807107640] fs setup took 0 secs [20081217-04:04:59.559273216] Syncing()...0 sec [20081217-04:04:59.561099030] Starting Actual Benchmark At: Wed Dec 17 04:04:59 2008 [20081217-04:04:59.573994644] [20081217-04:10:03.333349322] Syncing()...1 sec [20081217-04:10:03.336173611] FFSB benchmark finished at: Wed Dec 17 04:10:03 2008 [20081217-04:10:03.339168760] [20081217-04:10:03.342080015] Results: [20081217-04:10:03.358472609] Benchmark took 303.77 sec [20081217-04:10:03.360808056] [20081217-04:10:03.363389916] Total Results [20081217-04:10:03.378773060] =============== [20081217-04:10:03.381291655] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-04:10:03.383862253] ======= ============ ========= ======= =========== ========== [20081217-04:10:03.386531801] write : 4705280 15489.45 100.000% 100.000% 1.18GB/sec [20081217-04:10:03.389753177] - [20081217-04:10:03.392386784] 15489.45 Transactions per Second [20081217-04:10:03.394692953] [20081217-04:10:03.398641815] Throughput Results [20081217-04:10:03.414187599] =================== [20081217-04:10:03.416953522] Write Throughput: 1.18GB/sec [20081217-04:10:03.419313288] [20081217-04:10:03.421910726] System Call Latency statistics in millisecs [20081217-04:10:03.424719530] ===== [20081217-04:10:03.427550615] Min Avg Max Total Calls [20081217-04:10:03.430463477] ======== ======== ======== ============ [20081217-04:10:03.433242011] [ open] 0.008000 0.024819 0.277000 3676 [20081217-04:10:03.436320037] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-04:10:03.439126118] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-04:10:03.442185934] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-04:10:03.444964956] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-04:10:03.447775711] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-04:10:03.450382454] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-04:10:03.453020807] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-04:10:03.455949654] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-04:10:03.459938912] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-04:10:03.463345581] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-04:10:03.466380244] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-04:10:03.468974825] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-04:10:03.471737142] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-04:10:03.474946366] msec_range[13] 0.200000 - 0.500000 : 5 [20081217-04:10:03.477868104] msec_range[14] 0.100000 - 0.200000 : 20 [20081217-04:10:03.480612765] msec_range[15] 0.050000 - 0.100000 : 205 [20081217-04:10:03.483103025] msec_range[16] 0.020000 - 0.050000 : 1898 [20081217-04:10:03.485948804] msec_range[17] 0.010000 - 0.020000 : 1480 [20081217-04:10:03.488330563] msec_range[18] 0.000000 - 0.010000 : 68 [20081217-04:10:03.491221600] [20081217-04:10:03.494634236] [ write] 0.189000 1.022048 531.112000 4705280 [20081217-04:10:03.497428805] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-04:10:03.500115505] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-04:10:03.503025845] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-04:10:03.505686961] msec_range[3] 500.000000 - 1000.000000 : 2 [20081217-04:10:03.508130213] msec_range[4] 200.000000 - 500.000000 : 2426 [20081217-04:10:03.510731943] msec_range[5] 100.000000 - 200.000000 : 8709 [20081217-04:10:03.513221970] msec_range[6] 50.000000 - 100.000000 : 8816 [20081217-04:10:03.515471391] msec_range[7] 20.000000 - 50.000000 : 9104 [20081217-04:10:03.517579684] msec_range[8] 10.000000 - 20.000000 : 4134 [20081217-04:10:03.520048553] msec_range[9] 5.000000 - 10.000000 : 2431 [20081217-04:10:03.523041153] msec_range[10] 2.000000 - 5.000000 : 1909 [20081217-04:10:03.525823665] msec_range[11] 1.000000 - 2.000000 : 211244 [20081217-04:10:03.528713365] msec_range[12] 0.500000 - 1.000000 : 529439 [20081217-04:10:03.531431759] msec_range[13] 0.200000 - 0.500000 : 3926428 [20081217-04:10:03.535340615] msec_range[14] 0.100000 - 0.200000 : 638 [20081217-04:10:03.538224304] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-04:10:03.540658569] msec_range[16] 0.020000 - 0.050000 : 0 [20081217-04:10:03.543064033] msec_range[17] 0.010000 - 0.020000 : 0 [20081217-04:10:03.546039686] msec_range[18] 0.000000 - 0.010000 : 0 [20081217-04:10:03.548681179] [20081217-04:10:03.550982711] [ lseek] 0.000000 0.001892 1.758000 4705280 [20081217-04:10:03.553508942] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-04:10:03.556265815] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-04:10:03.558996655] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-04:10:03.562272317] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-04:10:03.565034988] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-04:10:03.568837239] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-04:10:03.571732339] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-04:10:03.575677143] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-04:10:03.578187975] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-04:10:03.580892706] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-04:10:03.584466040] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-04:10:03.587348890] msec_range[11] 1.000000 - 2.000000 : 14 [20081217-04:10:03.591824827] msec_range[12] 0.500000 - 1.000000 : 43 [20081217-04:10:03.594460095] msec_range[13] 0.200000 - 0.500000 : 14 [20081217-04:10:03.596960713] msec_range[14] 0.100000 - 0.200000 : 381 [20081217-04:10:03.599717878] msec_range[15] 0.050000 - 0.100000 : 3187 [20081217-04:10:03.602312048] msec_range[16] 0.020000 - 0.050000 : 26587 [20081217-04:10:03.605095340] msec_range[17] 0.010000 - 0.020000 : 9637 [20081217-04:10:03.612552920] msec_range[18] 0.000000 - 0.010000 : 4665417 [20081217-04:10:03.615322677] [20081217-04:10:03.617995727] [ close] 0.004000 0.010466 0.181000 3676 [20081217-04:10:03.620833490] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-04:10:03.623400540] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-04:10:03.625980279] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-04:10:03.628423960] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-04:10:03.630803447] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-04:10:03.633399881] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-04:10:03.635853734] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-04:10:03.637996997] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-04:10:03.640267454] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-04:10:03.642543904] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-04:10:03.644643729] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-04:10:03.646909376] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-04:10:03.649132000] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-04:10:03.651296575] msec_range[13] 0.200000 - 0.500000 : 0 [20081217-04:10:03.653780990] msec_range[14] 0.100000 - 0.200000 : 6 [20081217-04:10:03.656247383] msec_range[15] 0.050000 - 0.100000 : 33 [20081217-04:10:03.658702528] msec_range[16] 0.020000 - 0.050000 : 182 [20081217-04:10:03.661292733] msec_range[17] 0.010000 - 0.020000 : 1036 [20081217-04:10:03.664880647] msec_range[18] 0.000000 - 0.010000 : 2419 [20081217-04:10:03.667395994] [20081217-04:10:03.669791407] [20081217-04:10:03.672050050] [20081217-04:10:03.674475784] [20081217-04:10:03.677146204] 5.2% User Time [20081217-04:10:03.679568560] 86.9% System Time [20081217-04:10:03.681958016] 92.1% CPU Utilization [20081217-04:10:03.684385620] Profilers reporting [20081217-04:10:18.387353146] Profilers postprocessing [20081217-04:10:19.524073514] Stopping profiling. [20081217-04:10:19.528649701] Killing daemon. [20081217-04:10:20.701528282] Processing File : /autobench/logs/ffsb.random_writes_odirect__threads_0016.08-12-17_04.04.48/analysis/oprofile.001 [20081217-04:10:20.703559665] Processing File : /autobench/logs/ffsb.random_writes_odirect__threads_0016.08-12-17_04.04.48/analysis/oprofile-brief.001 [20081217-04:10:20.819438467] Processing File : mpstat.001 [20081217-04:10:20.821717254] Discovered mpstat_interval=[5] [20081217-04:10:21.371079746] Processing Directory : sar.breakout.001 [20081217-04:10:21.373338383] Discovered sar_interval=[5] [20081217-04:10:21.529828820] Processing File : iostat.001 [20081217-04:10:21.532072075] Discovered iostat_interval=[5] [20081217-04:10:23.027706281] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0300/xfs-baseline' [20081217-04:10:27.089697916] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081217-04:10:27.218615574] PROCESSING COMMAND : 'mount -t xfs /dev/ffsbdev1 /mnt/ffsb1' [20081217-04:10:27.484210097] PROCESSING COMMAND : 'run random_writes_odirect__threads_0128 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb num_threads=128' [20081217-04:10:27.529212424] new log requested [20081217-04:10:27.553922100] Running command ffsb [20081217-04:10:36.218670702] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs1/random_writes_odirect.ffsb [20081217-04:10:36.233327172] Importing argument : num_threads=128 [20081217-04:10:36.259930438] Found a xfs filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081217-04:10:36.347938004] Checking for sar... [20081217-04:10:36.350038650] found [20081217-04:10:36.405995520] Checking for sar... [20081217-04:10:36.408224304] found [20081217-04:10:36.463931605] Checking for sar... [20081217-04:10:36.466186559] found [20081217-04:10:36.596072463] Checking for binutils-2.18 ... Already installed. [20081217-04:10:36.600260617] mv: cannot stat `lib64/*': No such file or directory [20081217-04:10:36.603210969] rmdir: lib64: No such file or directory [20081217-04:10:36.663039014] Checking for gettext-0.17 ... Already installed. [20081217-04:10:36.704106732] popt32-1.10.4 already installed. [20081217-04:10:36.719344220] popt64-1.10.4 already installed. [20081217-04:10:36.749809236] Checking for oprofile-0.9.4-autobench ... Already installed. [20081217-04:10:36.801822023] opcontrol: oprofile 0.9.4 compiled on Nov 18 2008 20:40:15 [20081217-04:10:36.881432297] Daemon not running [20081217-04:10:36.904550983] Unloading oprofile module [20081217-04:10:37.008711644] Daemon not running [20081217-04:10:38.461145849] OPROFILE : using callgraph [5] [20081217-04:10:38.694689042] Daemon not running [20081217-04:10:38.696675085] Separate options: none [20081217-04:10:38.698828260] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081217-04:10:38.700991789] Image filter: none [20081217-04:10:38.702789526] Call-graph depth: 5 [20081217-04:10:38.762311434] FFSB version 6.0-RC2 started [20081217-04:10:38.764466405] [20081217-04:10:39.256378457] benchmark time = 300 [20081217-04:10:39.258621541] ThreadGroup 0 [20081217-04:10:39.260608789] ================ [20081217-04:10:39.262692274] num_threads = 128 [20081217-04:10:39.264850869] [20081217-04:10:39.266770652] read_random = off [20081217-04:10:39.268599127] read_size = 0 (0B) [20081217-04:10:39.270360000] read_blocksize = 0 (0B) [20081217-04:10:39.272217574] read_skip = off [20081217-04:10:39.274166016] read_skipsize = 0 (0B) [20081217-04:10:39.276113542] [20081217-04:10:39.277952993] write_random = on [20081217-04:10:39.279945684] write_size = 5242880 (5MB) [20081217-04:10:39.282061564] fsync_file = 0 [20081217-04:10:39.283879021] write_blocksize = 4096 (4KB) [20081217-04:10:39.285646507] wait time = 0 [20081217-04:10:39.287518999] [20081217-04:10:39.289418440] op weights [20081217-04:10:39.291201619] read = 0 (0.00%) [20081217-04:10:39.293089452] readall = 0 (0.00%) [20081217-04:10:39.294945370] write = 1 (100.00%) [20081217-04:10:39.296701085] create = 0 (0.00%) [20081217-04:10:39.298564268] append = 0 (0.00%) [20081217-04:10:39.300403720] delete = 0 (0.00%) [20081217-04:10:39.302167278] metaop = 0 (0.00%) [20081217-04:10:39.304047314] createdir = 0 (0.00%) [20081217-04:10:39.305884791] stat = 0 (0.00%) [20081217-04:10:39.307634656] writeall = 0 (0.00%) [20081217-04:10:39.309478233] writeall_fsync = 0 (0.00%) [20081217-04:10:39.311242861] open_close = 0 (0.00%) [20081217-04:10:39.313001292] write_fsync = 0 (0.00%) [20081217-04:10:39.314836932] create_fsync = 0 (0.00%) [20081217-04:10:39.316650779] append_fsync = 0 (0.00%) [20081217-04:10:39.318378361] [20081217-04:10:39.320213699] FileSystem /mnt/ffsb1 [20081217-04:10:39.322031295] ========== [20081217-04:10:39.323751581] num_dirs = 0 [20081217-04:10:39.325578366] starting files = 1024 [20081217-04:10:39.327379747] [20081217-04:10:39.329097802] min file size = 104857600 (100MB) [20081217-04:10:39.330922012] max file size = 104857600 (100MB) [20081217-04:10:39.332820048] directio = on [20081217-04:10:39.334592949] alignedio = on [20081217-04:10:39.336930711] bufferedio = off [20081217-04:10:39.339025149] [20081217-04:10:39.382630972] aging is off [20081217-04:10:39.384580795] current utilization = 4.47% [20081217-04:10:39.386440847] [20081217-04:10:39.388324940] checking existing fs: /mnt/ffsb1 [20081217-04:10:39.390210035] fs setup took 0 secs [20081217-04:10:40.024244877] Syncing()...0 sec [20081217-04:10:40.031837394] Starting Actual Benchmark At: Wed Dec 17 04:10:40 2008 [20081217-04:10:40.046315274] [20081217-04:15:46.923846264] Syncing()...1 sec [20081217-04:15:46.926559410] FFSB benchmark finished at: Wed Dec 17 04:15:46 2008 [20081217-04:15:46.929220064] [20081217-04:15:46.932019075] Results: [20081217-04:15:46.946065822] Benchmark took 306.90 sec [20081217-04:15:46.948878442] [20081217-04:15:46.951196936] Total Results [20081217-04:15:46.966822501] =============== [20081217-04:15:46.969560931] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081217-04:15:46.972067447] ======= ============ ========= ======= =========== ========== [20081217-04:15:46.974688174] write : 8625920 28106.71 100.000% 100.000% 2.14GB/sec [20081217-04:15:46.977128592] - [20081217-04:15:46.979498439] 28106.71 Transactions per Second [20081217-04:15:46.981953426] [20081217-04:15:46.985302593] Throughput Results [20081217-04:15:47.000390127] =================== [20081217-04:15:47.002748401] Write Throughput: 2.14GB/sec [20081217-04:15:47.005077522] [20081217-04:15:47.007545128] System Call Latency statistics in millisecs [20081217-04:15:47.009867557] ===== [20081217-04:15:47.012041545] Min Avg Max Total Calls [20081217-04:15:47.014367423] ======== ======== ======== ============ [20081217-04:15:47.018496834] [ open] 0.007000 0.027777 2.013000 6739 [20081217-04:15:47.021080168] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-04:15:47.023332066] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-04:15:47.025980397] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-04:15:47.028841146] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-04:15:47.032580127] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-04:15:47.035794036] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-04:15:47.038594396] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-04:15:47.041252969] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-04:15:47.044116639] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-04:15:47.047568561] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-04:15:47.050568308] msec_range[10] 2.000000 - 5.000000 : 1 [20081217-04:15:47.053474558] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-04:15:47.055992697] msec_range[12] 0.500000 - 1.000000 : 3 [20081217-04:15:47.058348902] msec_range[13] 0.200000 - 0.500000 : 31 [20081217-04:15:47.061761335] msec_range[14] 0.100000 - 0.200000 : 57 [20081217-04:15:47.064488423] msec_range[15] 0.050000 - 0.100000 : 145 [20081217-04:15:47.067507057] msec_range[16] 0.020000 - 0.050000 : 4737 [20081217-04:15:47.069942851] msec_range[17] 0.010000 - 0.020000 : 1725 [20081217-04:15:47.072728867] msec_range[18] 0.000000 - 0.010000 : 40 [20081217-04:15:47.075169052] [20081217-04:15:47.077754305] [ write] 0.187000 4.493059 2424.518066 8625920 [20081217-04:15:47.080349067] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-04:15:47.082781910] msec_range[1] 2000.000000 - 5000.000000 : 14 [20081217-04:15:47.084995116] msec_range[2] 1000.000000 - 2000.000000 : 608 [20081217-04:15:47.087397279] msec_range[3] 500.000000 - 1000.000000 : 4072 [20081217-04:15:47.089829143] msec_range[4] 200.000000 - 500.000000 : 22942 [20081217-04:15:47.092160763] msec_range[5] 100.000000 - 200.000000 : 40860 [20081217-04:15:47.094374533] msec_range[6] 50.000000 - 100.000000 : 53329 [20081217-04:15:47.097226576] msec_range[7] 20.000000 - 50.000000 : 59391 [20081217-04:15:47.099745069] msec_range[8] 10.000000 - 20.000000 : 96876 [20081217-04:15:47.102057344] msec_range[9] 5.000000 - 10.000000 : 250795 [20081217-04:15:47.104544921] msec_range[10] 2.000000 - 5.000000 : 3029270 [20081217-04:15:47.107776040] msec_range[11] 1.000000 - 2.000000 : 2401436 [20081217-04:15:47.110570020] msec_range[12] 0.500000 - 1.000000 : 1764039 [20081217-04:15:47.113296031] msec_range[13] 0.200000 - 0.500000 : 902063 [20081217-04:15:47.115693764] msec_range[14] 0.100000 - 0.200000 : 225 [20081217-04:15:47.119278292] msec_range[15] 0.050000 - 0.100000 : 0 [20081217-04:15:47.121885490] msec_range[16] 0.020000 - 0.050000 : 0 [20081217-04:15:47.124710540] msec_range[17] 0.010000 - 0.020000 : 0 [20081217-04:15:47.126978700] msec_range[18] 0.000000 - 0.010000 : 0 [20081217-04:15:47.129377930] [20081217-04:15:47.131890296] [ lseek] 0.000000 0.002103 10.609000 8625920 [20081217-04:15:47.134296486] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-04:15:47.136873412] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-04:15:47.139322209] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-04:15:47.141949800] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-04:15:47.144542583] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-04:15:47.147750194] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-04:15:47.150379937] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-04:15:47.153007505] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-04:15:47.156399482] msec_range[8] 10.000000 - 20.000000 : 1 [20081217-04:15:47.159873714] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-04:15:47.162989005] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-04:15:47.165591989] msec_range[11] 1.000000 - 2.000000 : 8 [20081217-04:15:47.169780334] msec_range[12] 0.500000 - 1.000000 : 168 [20081217-04:15:47.172219710] msec_range[13] 0.200000 - 0.500000 : 3227 [20081217-04:15:47.175157611] msec_range[14] 0.100000 - 0.200000 : 5920 [20081217-04:15:47.177618848] msec_range[15] 0.050000 - 0.100000 : 9496 [20081217-04:15:47.180234125] msec_range[16] 0.020000 - 0.050000 : 20630 [20081217-04:15:47.182674744] msec_range[17] 0.010000 - 0.020000 : 15859 [20081217-04:15:47.186473161] msec_range[18] 0.000000 - 0.010000 : 8570611 [20081217-04:15:47.189041679] [20081217-04:15:47.192139465] [ close] 0.003000 0.011541 0.404000 6739 [20081217-04:15:47.194582896] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081217-04:15:47.197344021] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081217-04:15:47.199813348] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081217-04:15:47.202140734] msec_range[3] 500.000000 - 1000.000000 : 0 [20081217-04:15:47.204618425] msec_range[4] 200.000000 - 500.000000 : 0 [20081217-04:15:47.207541194] msec_range[5] 100.000000 - 200.000000 : 0 [20081217-04:15:47.210319020] msec_range[6] 50.000000 - 100.000000 : 0 [20081217-04:15:47.212575461] msec_range[7] 20.000000 - 50.000000 : 0 [20081217-04:15:47.214869087] msec_range[8] 10.000000 - 20.000000 : 0 [20081217-04:15:47.217379851] msec_range[9] 5.000000 - 10.000000 : 0 [20081217-04:15:47.219926917] msec_range[10] 2.000000 - 5.000000 : 0 [20081217-04:15:47.222213314] msec_range[11] 1.000000 - 2.000000 : 0 [20081217-04:15:47.224451418] msec_range[12] 0.500000 - 1.000000 : 0 [20081217-04:15:47.226773828] msec_range[13] 0.200000 - 0.500000 : 8 [20081217-04:15:47.229069368] msec_range[14] 0.100000 - 0.200000 : 30 [20081217-04:15:47.231295783] msec_range[15] 0.050000 - 0.100000 : 44 [20081217-04:15:47.233569045] msec_range[16] 0.020000 - 0.050000 : 173 [20081217-04:15:47.235746696] msec_range[17] 0.010000 - 0.020000 : 2915 [20081217-04:15:47.237948324] msec_range[18] 0.000000 - 0.010000 : 3569 [20081217-04:15:47.240206104] [20081217-04:15:47.242375496] [20081217-04:15:47.244504011] [20081217-04:15:47.246996446] [20081217-04:15:47.250246566] 9.9% User Time [20081217-04:15:47.252521084] 174.9% System Time [20081217-04:15:47.254750222] 184.8% CPU Utilization [20081217-04:15:47.256973133] Profilers reporting [20081217-04:16:03.449743050] Profilers postprocessing [20081217-04:16:04.586154939] Stopping profiling. [20081217-04:16:04.591595608] Killing daemon. [20081217-04:16:05.765496055] Processing File : /autobench/logs/ffsb.random_writes_odirect__threads_0128.08-12-17_04.10.27/analysis/oprofile.001 [20081217-04:16:05.767695498] Processing File : /autobench/logs/ffsb.random_writes_odirect__threads_0128.08-12-17_04.10.27/analysis/oprofile-brief.001 [20081217-04:16:05.884260317] Processing File : mpstat.001 [20081217-04:16:05.886294446] Discovered mpstat_interval=[5] [20081217-04:16:06.441968742] Processing Directory : sar.breakout.001 [20081217-04:16:06.444353268] Discovered sar_interval=[5] [20081217-04:16:06.584644153] Processing File : iostat.001 [20081217-04:16:06.586945263] Discovered iostat_interval=[5] [20081217-04:16:08.890573094] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs1/2008-12-17_0300/xfs-baseline'