[20081216-15:03:12.285339942] PROCESSING COMMAND : 'clearprofilers' [20081216-15:03:12.551183898] PROCESSING COMMAND : 'useprofiler iostat 5' [20081216-15:03:12.658633200] Checking for sar... [20081216-15:03:12.661742255] found [20081216-15:03:12.800358821] PROCESSING COMMAND : 'useprofiler sar 5' [20081216-15:03:12.911055647] Checking for sar... [20081216-15:03:12.913999966] found [20081216-15:03:13.053866664] PROCESSING COMMAND : 'useprofiler mpstat 5' [20081216-15:03:13.162083046] Checking for sar... [20081216-15:03:13.164444564] found [20081216-15:03:13.334617731] PROCESSING COMMAND : 'useprofiler oprofile' [20081216-15:03:13.576428602] Checking for binutils-2.18 ... [20081216-15:03:13.591612692] Already installed. [20081216-15:03:13.648829861] Checking for oprofile-0.9.4-autobench ... [20081216-15:03:13.667207091] Already installed. [20081216-15:03:13.760256449] opcontrol: oprofile 0.9.4 compiled on Nov 19 2008 09:09:21 [20081216-15:03:13.896655146] Daemon not running [20081216-15:03:19.243676064] OPROFILE : using callgraph [5] [20081216-15:03:19.472615584] Daemon not running [20081216-15:03:19.475335532] Separate options: none [20081216-15:03:19.477375718] vmlinux file: /boot/vmlinux-2.6.27.9-frame-pointers [20081216-15:03:19.479435667] Image filter: none [20081216-15:03:19.481454550] Call-graph depth: 5 [20081216-15:03:19.686234868] PROCESSING COMMAND : 'umount /mnt/ffsb1 > /dev/null 2>&1' [20081216-15:03:19.760207823] PROCESSING COMMAND : 'set-sched noop' [20081216-15:03:20.151727006] PROCESSING COMMAND : 'mkresultdirs hks.austin.ibm.com benchmarks/results/btrfs/ffsb btrfs2 2008-12-16_1503 ext3-baseline' [20081216-15:03:20.656630751] Connecting to hks.austin.ibm.com... [20081216-15:03:20.660457992] Remote working directory: /opt [20081216-15:03:20.662781684] Remote working directory: /opt/benchmarks/results/btrfs/ffsb [20081216-15:03:20.664794855] Couldn't create directory: Failure [20081216-15:03:20.666871849] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs2 [20081216-15:03:20.668917524] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs2 [20081216-15:03:20.670768398] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-16_1503 [20081216-15:03:20.672659612] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-16_1503 [20081216-15:03:20.674498056] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-16_1503/ext3-baseline [20081216-15:03:20.742318172] PROCESSING COMMAND : 'mkfs.ext3 -V 2>&1' [20081216-15:03:20.791024646] mke2fs 1.41.2 (02-Oct-2008) [20081216-15:03:20.793291281] Using EXT2FS Library version 1.41.2 [20081216-15:03:20.884077481] PROCESSING COMMAND : 'mkfs.ext3 -F /dev/ffsbdev1' [20081216-15:03:20.905137554] mke2fs 1.41.2 (02-Oct-2008) [20081216-15:03:20.928229260] Filesystem label= [20081216-15:03:20.930488153] OS type: Linux [20081216-15:03:20.932386308] Block size=4096 (log=2) [20081216-15:03:20.934540492] Fragment size=4096 (log=2) [20081216-15:03:20.936839010] 4481024 inodes, 17921750 blocks [20081216-15:03:20.938618434] 896087 blocks (5.00%) reserved for the super user [20081216-15:03:20.940702792] First data block=0 [20081216-15:03:20.942551921] Maximum filesystem blocks=4294967296 [20081216-15:03:20.944381980] 547 block groups [20081216-15:03:20.946131101] 32768 blocks per group, 32768 fragments per group [20081216-15:03:20.947993683] 8192 inodes per group [20081216-15:03:20.949870396] Superblock backups stored on blocks: [20081216-15:03:20.951592459] 32768, 98304, 163840, 229376, 294912, 819200, 884736, 1605632, 2654208, [20081216-15:03:20.953381283] 4096000, 7962624, 11239424 [20081216-15:03:20.955165125] [20081216-15:03:33.079855511] Writing inode tables: 0/547 1/547 2/547 3/547 4/547 5/547 6/547 7/547 8/547 9/547 10/547 11/547 12/547 13/547 14/547 15/547 16/547 17/547 18/547 19/547 20/547 21/547 22/547 23/547 24/547 25/547 26/547 27/547 28/547 29/547 30/547 31/547 32/547 33/547 34/547 35/547 36/547 37/547 38/547 39/547 40/547 41/547 42/547 43/547 44/547 45/547 46/547 47/547 48/547 49/547 50/547 51/547 52/547 53/547 54/547 55/547 56/547 57/547 58/547 59/547 60/547 61/547 62/547 63/547 64/547 65/547 66/547 67/547 68/547 69/547 70/547 71/547 72/547 73/547 74/547 75/547 76/547 77/547 78/547 79/547 80/547 81/547 82/547 83/547 84/547 85/547 86/547 87/547 88/547 89/547 90/547 91/547 92/547 93/547 94/547 95/547 96/547 97/547 98/547 99/547100/547101/547102/547103/547104/547105/547106/547107/547108/547109/547110/547111/547112/547113/547114/547115/547116/547117/547118/547119/547120/547121/547122/547123/547124/547125/547126/547127/547128/547129/547130/547131/547132/547133/547134/547135/547136/547137/547138/547139/547140/547141/547142/547143/547144/547145/547146/547147/547148/547149/547150/547151/547152/547153/547154/547155/547156/547157/547158/547159/547160/547161/547162/547163/547164/547165/547166/547167/547168/547169/547170/547171/547172/547173/547174/547175/547176/547177/547178/547179/547180/547181/547182/547183/547184/547185/547186/547187/547188/547189/547190/547191/547192/547193/547194/547195/547196/547197/547198/547199/547200/547201/547202/547203/547204/547205/547206/547207/547208/547209/547210/547211/547212/547213/547214/547215/547216/547217/547218/547219/547220/547221/547222/547223/547224/547225/547226/547227/547228/547229/547230/547231/547232/547233/547234/547235/547236/547237/547238/547239/547240/547241/547242/547243/547244/547245/547246/547247/547248/547249/547250/547251/547252/547253/547254/547255/547256/547257/547258/547259/547260/547261/547262/547263/547264/547265/547266/547267/547268/547269/547270/547271/547272/547273/547274/547275/547276/547277/547278/547279/547280/547281/547282/547283/547284/547285/547286/547287/547288/547289/547290/547291/547292/547293/547294/547295/547296/547297/547298/547299/547300/547301/547302/547303/547304/547305/547306/547307/547308/547309/547310/547311/547312/547313/547314/547315/547316/547317/547318/547319/547320/547321/547322/547323/547324/547325/547326/547327/547328/547329/547330/547331/547332/547333/547334/547335/547336/547337/547338/547339/547340/547341/547342/547343/547344/547345/547346/547347/547348/547349/547350/547351/547352/547353/547354/547355/547356/547357/547358/547359/547360/547361/547362/547363/547364/547365/547366/547367/547368/547369/547370/547371/547372/547373/547374/547375/547376/547377/547378/547379/547380/547381/547382/547383/547384/547385/547386/547387/547388/547389/547390/547391/547392/547393/547394/547395/547396/547397/547398/547399/547400/547401/547402/547403/547404/547405/547406/547407/547408/547409/547410/547411/547412/547413/547414/547415/547416/547417/547418/547419/547420/547421/547422/547423/547424/547425/547426/547427/547428/547429/547430/547431/547432/547433/547434/547435/547436/547437/547438/547439/547440/547441/547442/547443/547444/547445/547446/547447/547448/547449/547450/547451/547452/547453/547454/547455/547456/547457/547458/547459/547460/547461/547462/547463/547464/547465/547466/547467/547468/547469/547470/547471/547472/547473/547474/547475/547476/547477/547478/547479/547480/547481/547482/547483/547484/547485/547486/547487/547488/547489/547490/547491/547492/547493/547494/547495/547496/547497/547498/547499/547500/547501/547502/547503/547504/547505/547506/547507/547508/547509/547510/547511/547512/547513/547514/547515/547516/547517/547518/547519/547520/547521/547522/547523/547524/547525/547526/547527/547528/547529/547530/547531/547532/547533/547534/547535/547536/547537/547538/547539/547540/547541/547542/547543/547544/547545/547546/547done [20081216-15:03:34.751945740] Creating journal (32768 blocks): done [20081216-15:03:38.568330803] Writing superblocks and filesystem accounting information: done [20081216-15:03:39.012755401] [20081216-15:03:39.015503550] This filesystem will be automatically checked every 38 mounts or [20081216-15:03:39.018362159] 180 days, whichever comes first. Use tune2fs -c or -i to override. [20081216-15:03:39.177537794] PROCESSING COMMAND : 'mount -t ext3 /dev/ffsbdev1 /mnt/ffsb1' [20081216-15:03:39.305112000] PROCESSING COMMAND : 'run sequential_reads__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb num_threads=1' [20081216-15:03:39.359040988] new log requested [20081216-15:03:39.418099443] Running command ffsb [20081216-15:03:47.713244642] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb [20081216-15:03:47.732654383] Importing argument : num_threads=1 [20081216-15:03:47.758708044] Found a ext3 filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081216-15:03:47.838845286] FFSB version 6.0-RC2 started [20081216-15:03:47.840993964] [20081216-15:03:47.843104059] benchmark time = 300 [20081216-15:03:47.845105151] ThreadGroup 0 [20081216-15:03:47.847322472] ================ [20081216-15:03:47.849477113] num_threads = 1 [20081216-15:03:47.851377590] [20081216-15:03:47.853185020] read_random = off [20081216-15:03:47.855055794] read_size = 0 (0B) [20081216-15:03:47.856923811] read_blocksize = 4096 (4KB) [20081216-15:03:47.858711169] read_skip = off [20081216-15:03:47.860698469] read_skipsize = 0 (0B) [20081216-15:03:47.862669977] [20081216-15:03:47.864582251] write_random = off [20081216-15:03:47.866353452] write_size = 0 (0B) [20081216-15:03:47.868270263] fsync_file = 0 [20081216-15:03:47.870154597] write_blocksize = 0 (0B) [20081216-15:03:47.871958216] wait time = 0 [20081216-15:03:47.873859800] [20081216-15:03:47.875654525] op weights [20081216-15:03:47.877483991] read = 0 (0.00%) [20081216-15:03:47.879259598] readall = 1 (100.00%) [20081216-15:03:47.881166725] write = 0 (0.00%) [20081216-15:03:47.883044912] create = 0 (0.00%) [20081216-15:03:47.884850538] append = 0 (0.00%) [20081216-15:03:47.886727209] delete = 0 (0.00%) [20081216-15:03:47.888554680] metaop = 0 (0.00%) [20081216-15:03:47.890400285] createdir = 0 (0.00%) [20081216-15:03:47.892132880] stat = 0 (0.00%) [20081216-15:03:47.894037258] writeall = 0 (0.00%) [20081216-15:03:47.895904926] writeall_fsync = 0 (0.00%) [20081216-15:03:47.897682812] open_close = 0 (0.00%) [20081216-15:03:47.899549903] write_fsync = 0 (0.00%) [20081216-15:03:47.901364989] create_fsync = 0 (0.00%) [20081216-15:03:47.903202193] append_fsync = 0 (0.00%) [20081216-15:03:47.904986359] [20081216-15:03:47.906871177] FileSystem /mnt/ffsb1 [20081216-15:03:47.908728154] ========== [20081216-15:03:47.910513594] num_dirs = 0 [20081216-15:03:47.912415819] starting files = 1024 [20081216-15:03:47.914212536] [20081216-15:03:47.915981641] min file size = 36700160 (35MB) [20081216-15:03:47.917822323] max file size = 36700160 (35MB) [20081216-15:03:47.919612049] directio = off [20081216-15:03:47.921440268] alignedio = on [20081216-15:03:47.923165350] bufferedio = off [20081216-15:03:47.925056302] [20081216-15:03:47.926872541] aging is off [20081216-15:03:47.928632599] current utilization = 0.26% [20081216-15:03:47.930468914] [20081216-15:03:47.932351243] checking existing fs: /mnt/ffsb1 [20081216-15:03:47.934111422] opendir: No such file or directory [20081216-15:03:47.935997277] recreating new fileset [20081216-15:11:22.283940460] fs setup took 454 secs [20081216-15:11:25.999911928] Syncing()...3 sec [20081216-15:11:26.002464510] Starting Actual Benchmark At: Tue Dec 16 15:11:25 2008 [20081216-15:11:26.052634681] [20081216-15:16:28.015579441] Syncing()...0 sec [20081216-15:16:28.062223094] FFSB benchmark finished at: Tue Dec 16 15:16:27 2008 [20081216-15:16:28.064994177] [20081216-15:16:28.067710075] Results: [20081216-15:16:28.102265307] Benchmark took 301.80 sec [20081216-15:16:28.104337034] [20081216-15:16:28.106930497] Total Results [20081216-15:16:28.121774816] =============== [20081216-15:16:28.124399222] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081216-15:16:28.127134050] ======= ============ ========= ======= =========== ========== [20081216-15:16:28.129388308] readall : 7230720 23958.70 100.000% 100.000% 93.6MB/sec [20081216-15:16:28.131851668] - [20081216-15:16:28.134283327] 23958.70 Transactions per Second [20081216-15:16:28.136667078] [20081216-15:16:28.148178977] Throughput Results [20081216-15:16:28.163036561] =================== [20081216-15:16:28.165544112] Read Throughput: 93.6MB/sec [20081216-15:16:28.167901886] [20081216-15:16:28.170447220] System Call Latency statistics in millisecs [20081216-15:16:28.172775059] ===== [20081216-15:16:28.175150848] Min Avg Max Total Calls [20081216-15:16:28.177628971] ======== ======== ======== ============ [20081216-15:16:28.180085127] [ open] 0.012000 0.105713 7.819000 807 [20081216-15:16:28.182239701] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081216-15:16:28.184502121] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081216-15:16:28.186971752] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081216-15:16:28.189393712] msec_range[3] 500.000000 - 1000.000000 : 0 [20081216-15:16:28.191581987] msec_range[4] 200.000000 - 500.000000 : 0 [20081216-15:16:28.193710032] msec_range[5] 100.000000 - 200.000000 : 0 [20081216-15:16:28.195823017] msec_range[6] 50.000000 - 100.000000 : 0 [20081216-15:16:28.198274540] msec_range[7] 20.000000 - 50.000000 : 0 [20081216-15:16:28.200573023] msec_range[8] 10.000000 - 20.000000 : 0 [20081216-15:16:28.202705310] msec_range[9] 5.000000 - 10.000000 : 5 [20081216-15:16:28.204963462] msec_range[10] 2.000000 - 5.000000 : 4 [20081216-15:16:28.207143038] msec_range[11] 1.000000 - 2.000000 : 0 [20081216-15:16:28.209385261] msec_range[12] 0.500000 - 1.000000 : 0 [20081216-15:16:28.211528509] msec_range[13] 0.200000 - 0.500000 : 4 [20081216-15:16:28.213751311] msec_range[14] 0.100000 - 0.200000 : 0 [20081216-15:16:28.215820261] msec_range[15] 0.050000 - 0.100000 : 378 [20081216-15:16:28.218017796] msec_range[16] 0.020000 - 0.050000 : 379 [20081216-15:16:28.220249278] msec_range[17] 0.010000 - 0.020000 : 37 [20081216-15:16:28.222443959] msec_range[18] 0.000000 - 0.010000 : 0 [20081216-15:16:28.224741224] [20081216-15:16:28.227860590] [ read] 0.004000 0.041254 116.338997 7230720 [20081216-15:16:28.231726328] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081216-15:16:28.234629089] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081216-15:16:28.237058912] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081216-15:16:28.239625431] msec_range[3] 500.000000 - 1000.000000 : 0 [20081216-15:16:28.242038536] msec_range[4] 200.000000 - 500.000000 : 0 [20081216-15:16:28.244165664] msec_range[5] 100.000000 - 200.000000 : 1 [20081216-15:16:28.246575940] msec_range[6] 50.000000 - 100.000000 : 0 [20081216-15:16:28.249165914] msec_range[7] 20.000000 - 50.000000 : 30 [20081216-15:16:28.251480290] msec_range[8] 10.000000 - 20.000000 : 5718 [20081216-15:16:28.253921697] msec_range[9] 5.000000 - 10.000000 : 6078 [20081216-15:16:28.256236176] msec_range[10] 2.000000 - 5.000000 : 37901 [20081216-15:16:28.258491906] msec_range[11] 1.000000 - 2.000000 : 1205 [20081216-15:16:28.260583032] msec_range[12] 0.500000 - 1.000000 : 5884 [20081216-15:16:28.262852913] msec_range[13] 0.200000 - 0.500000 : 685 [20081216-15:16:28.265029160] msec_range[14] 0.100000 - 0.200000 : 962 [20081216-15:16:28.267271931] msec_range[15] 0.050000 - 0.100000 : 639 [20081216-15:16:28.269553454] msec_range[16] 0.020000 - 0.050000 : 1470 [20081216-15:16:28.272539900] msec_range[17] 0.010000 - 0.020000 : 575932 [20081216-15:16:28.274868516] msec_range[18] 0.000000 - 0.010000 : 6594215 [20081216-15:16:28.277347855] [20081216-15:16:28.279778713] [ close] 0.003000 0.007170 0.017000 807 [20081216-15:16:28.282148434] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081216-15:16:28.284217693] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081216-15:16:28.286621669] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081216-15:16:28.289189256] msec_range[3] 500.000000 - 1000.000000 : 0 [20081216-15:16:28.291445879] msec_range[4] 200.000000 - 500.000000 : 0 [20081216-15:16:28.293793821] msec_range[5] 100.000000 - 200.000000 : 0 [20081216-15:16:28.296042807] msec_range[6] 50.000000 - 100.000000 : 0 [20081216-15:16:28.298258150] msec_range[7] 20.000000 - 50.000000 : 0 [20081216-15:16:28.300401098] msec_range[8] 10.000000 - 20.000000 : 0 [20081216-15:16:28.302600591] msec_range[9] 5.000000 - 10.000000 : 0 [20081216-15:16:28.304814156] msec_range[10] 2.000000 - 5.000000 : 0 [20081216-15:16:28.306889704] msec_range[11] 1.000000 - 2.000000 : 0 [20081216-15:16:28.309157715] msec_range[12] 0.500000 - 1.000000 : 0 [20081216-15:16:28.311395070] msec_range[13] 0.200000 - 0.500000 : 0 [20081216-15:16:28.313754243] msec_range[14] 0.100000 - 0.200000 : 0 [20081216-15:16:28.315917213] msec_range[15] 0.050000 - 0.100000 : 0 [20081216-15:16:28.318284947] msec_range[16] 0.020000 - 0.050000 : 0 [20081216-15:16:28.320737392] msec_range[17] 0.010000 - 0.020000 : 134 [20081216-15:16:28.322955130] msec_range[18] 0.000000 - 0.010000 : 673 [20081216-15:16:28.325184611] [20081216-15:16:28.327385763] [20081216-15:16:28.329647275] [20081216-15:16:28.331800872] [20081216-15:16:28.334059737] 1.6% User Time [20081216-15:16:28.336728203] 18.9% System Time [20081216-15:16:28.339264664] 20.5% CPU Utilization [20081216-15:16:28.341709508] Profilers reporting [20081216-15:16:28.467224977] /autobench/scripts/doprofilers: line 33: 18158 Terminated ${CMDS[$i]} [20081216-15:16:28.493149517] /autobench/scripts/doprofilers: line 33: 18164 Terminated ${CMDS[$i]} [20081216-15:16:28.518094470] /autobench/scripts/doprofilers: line 33: 18187 Terminated ${CMDS[$i]} [20081216-15:16:43.112962999] Profilers postprocessing [20081216-15:16:43.387460280] Processing File : iostat.001 [20081216-15:16:43.389732064] Discovered iostat_interval=[5] [20081216-15:16:43.962128493] Processing Directory : sar.breakout.001 [20081216-15:16:43.964395185] Discovered sar_interval=[5] [20081216-15:16:44.131797683] Processing File : mpstat.001 [20081216-15:16:44.133974522] Discovered mpstat_interval=[5] [20081216-15:16:45.266719158] Stopping profiling. [20081216-15:16:45.270975319] Killing daemon. [20081216-15:16:47.539998500] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0001.08-12-16_15.03.39/analysis/oprofile.001 [20081216-15:16:47.542349996] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0001.08-12-16_15.03.39/analysis/oprofile-brief.001 [20081216-15:16:52.480478442] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-16_1503/ext3-baseline' [20081216-15:16:54.655661238] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081216-15:16:55.218782388] PROCESSING COMMAND : 'mount -t ext3 /dev/ffsbdev1 /mnt/ffsb1' [20081216-15:16:55.342224271] PROCESSING COMMAND : 'run sequential_reads__threads_0008 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb num_threads=8' [20081216-15:16:55.396901419] new log requested [20081216-15:16:55.431978087] Running command ffsb [20081216-15:17:03.466866807] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb [20081216-15:17:03.480461413] Importing argument : num_threads=8 [20081216-15:17:03.506849338] Found a ext3 filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081216-15:17:03.586136878] FFSB version 6.0-RC2 started [20081216-15:17:03.588375974] [20081216-15:17:03.612859250] benchmark time = 300 [20081216-15:17:03.615028069] ThreadGroup 0 [20081216-15:17:03.616894330] ================ [20081216-15:17:03.618679215] num_threads = 8 [20081216-15:17:03.620584186] [20081216-15:17:03.622596389] read_random = off [20081216-15:17:03.624662966] read_size = 0 (0B) [20081216-15:17:03.626639816] read_blocksize = 4096 (4KB) [20081216-15:17:03.628568582] read_skip = off [20081216-15:17:03.630411632] read_skipsize = 0 (0B) [20081216-15:17:03.632290507] [20081216-15:17:03.634053732] write_random = off [20081216-15:17:03.635899120] write_size = 0 (0B) [20081216-15:17:03.637676734] fsync_file = 0 [20081216-15:17:03.639545377] write_blocksize = 0 (0B) [20081216-15:17:03.641321182] wait time = 0 [20081216-15:17:03.643134802] [20081216-15:17:03.644882671] op weights [20081216-15:17:03.646723110] read = 0 (0.00%) [20081216-15:17:03.648508886] readall = 1 (100.00%) [20081216-15:17:03.650307228] write = 0 (0.00%) [20081216-15:17:03.652043687] create = 0 (0.00%) [20081216-15:17:03.653883836] append = 0 (0.00%) [20081216-15:17:03.655662280] delete = 0 (0.00%) [20081216-15:17:03.657518139] metaop = 0 (0.00%) [20081216-15:17:03.659253462] createdir = 0 (0.00%) [20081216-15:17:03.661084024] stat = 0 (0.00%) [20081216-15:17:03.662876430] writeall = 0 (0.00%) [20081216-15:17:03.664714242] writeall_fsync = 0 (0.00%) [20081216-15:17:03.666617759] open_close = 0 (0.00%) [20081216-15:17:03.668393721] write_fsync = 0 (0.00%) [20081216-15:17:03.670248608] create_fsync = 0 (0.00%) [20081216-15:17:03.672073151] append_fsync = 0 (0.00%) [20081216-15:17:03.673817090] [20081216-15:17:03.675672691] FileSystem /mnt/ffsb1 [20081216-15:17:03.677546904] ========== [20081216-15:17:03.679293303] num_dirs = 0 [20081216-15:17:03.681077914] starting files = 1024 [20081216-15:17:03.682819160] [20081216-15:17:03.684680957] min file size = 36700160 (35MB) [20081216-15:17:03.686429578] max file size = 36700160 (35MB) [20081216-15:17:03.688252634] directio = off [20081216-15:17:03.689992913] alignedio = on [20081216-15:17:03.691790229] bufferedio = off [20081216-15:17:03.693588127] [20081216-15:17:03.695431989] aging is off [20081216-15:17:03.697284147] current utilization = 52.33% [20081216-15:17:03.699022246] [20081216-15:17:03.700852395] checking existing fs: /mnt/ffsb1 [20081216-15:17:03.735819572] fs setup took 0 secs [20081216-15:17:04.144079300] Syncing()...0 sec [20081216-15:17:04.145881605] Starting Actual Benchmark At: Tue Dec 16 15:17:04 2008 [20081216-15:17:04.158685357] [20081216-15:22:08.536073382] Syncing()...0 sec [20081216-15:22:08.565000759] FFSB benchmark finished at: Tue Dec 16 15:22:08 2008 [20081216-15:22:08.567940601] [20081216-15:22:08.570674208] Results: [20081216-15:22:08.601273107] Benchmark took 304.24 sec [20081216-15:22:08.603887196] [20081216-15:22:08.606416805] Total Results [20081216-15:22:08.634267782] =============== [20081216-15:22:08.636545216] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081216-15:22:08.639066600] ======= ============ ========= ======= =========== ========== [20081216-15:22:08.641281749] readall : 6254080 20556.49 100.000% 100.000% 80.3MB/sec [20081216-15:22:08.644012125] - [20081216-15:22:08.646576810] 20556.49 Transactions per Second [20081216-15:22:08.648994851] [20081216-15:22:08.651143501] Throughput Results [20081216-15:22:08.666047292] =================== [20081216-15:22:08.668626110] Read Throughput: 80.3MB/sec [20081216-15:22:08.671356814] [20081216-15:22:08.673857120] System Call Latency statistics in millisecs [20081216-15:22:08.677081153] ===== [20081216-15:22:08.680046993] Min Avg Max Total Calls [20081216-15:22:08.682522659] ======== ======== ======== ============ [20081216-15:22:08.685132829] [ open] 0.006000 15.418711 2012.569946 698 [20081216-15:22:08.687836849] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081216-15:22:08.690348032] msec_range[1] 2000.000000 - 5000.000000 : 1 [20081216-15:22:08.693090339] msec_range[2] 1000.000000 - 2000.000000 : 3 [20081216-15:22:08.695340520] msec_range[3] 500.000000 - 1000.000000 : 3 [20081216-15:22:08.721999059] msec_range[4] 200.000000 - 500.000000 : 5 [20081216-15:22:08.724426062] msec_range[5] 100.000000 - 200.000000 : 6 [20081216-15:22:08.726679814] msec_range[6] 50.000000 - 100.000000 : 9 [20081216-15:22:08.729163528] msec_range[7] 20.000000 - 50.000000 : 1 [20081216-15:22:08.731394084] msec_range[8] 10.000000 - 20.000000 : 1 [20081216-15:22:08.733645794] msec_range[9] 5.000000 - 10.000000 : 1 [20081216-15:22:08.735711092] msec_range[10] 2.000000 - 5.000000 : 0 [20081216-15:22:08.737871947] msec_range[11] 1.000000 - 2.000000 : 1 [20081216-15:22:08.739944474] msec_range[12] 0.500000 - 1.000000 : 10 [20081216-15:22:08.742119580] msec_range[13] 0.200000 - 0.500000 : 14 [20081216-15:22:08.744202522] msec_range[14] 0.100000 - 0.200000 : 2 [20081216-15:22:08.746672108] msec_range[15] 0.050000 - 0.100000 : 64 [20081216-15:22:08.748840642] msec_range[16] 0.020000 - 0.050000 : 437 [20081216-15:22:08.750990838] msec_range[17] 0.010000 - 0.020000 : 136 [20081216-15:22:08.753074192] msec_range[18] 0.000000 - 0.010000 : 4 [20081216-15:22:08.755283906] [20081216-15:22:08.757381997] [ read] 0.001000 0.385278 2304.239014 6254080 [20081216-15:22:08.759575832] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081216-15:22:08.761644222] msec_range[1] 2000.000000 - 5000.000000 : 98 [20081216-15:22:08.763799587] msec_range[2] 1000.000000 - 2000.000000 : 271 [20081216-15:22:08.765894746] msec_range[3] 500.000000 - 1000.000000 : 825 [20081216-15:22:08.768025950] msec_range[4] 200.000000 - 500.000000 : 1943 [20081216-15:22:08.770101052] msec_range[5] 100.000000 - 200.000000 : 1715 [20081216-15:22:08.772664142] msec_range[6] 50.000000 - 100.000000 : 2100 [20081216-15:22:08.774799028] msec_range[7] 20.000000 - 50.000000 : 739 [20081216-15:22:08.776978226] msec_range[8] 10.000000 - 20.000000 : 4758 [20081216-15:22:08.779059308] msec_range[9] 5.000000 - 10.000000 : 5524 [20081216-15:22:08.781271642] msec_range[10] 2.000000 - 5.000000 : 25601 [20081216-15:22:08.783416960] msec_range[11] 1.000000 - 2.000000 : 478 [20081216-15:22:08.785612672] msec_range[12] 0.500000 - 1.000000 : 4081 [20081216-15:22:08.787713517] msec_range[13] 0.200000 - 0.500000 : 1631 [20081216-15:22:08.790083640] msec_range[14] 0.100000 - 0.200000 : 617 [20081216-15:22:08.792503719] msec_range[15] 0.050000 - 0.100000 : 852 [20081216-15:22:08.794964142] msec_range[16] 0.020000 - 0.050000 : 1663 [20081216-15:22:08.797259527] msec_range[17] 0.010000 - 0.020000 : 122292 [20081216-15:22:08.799634828] msec_range[18] 0.000000 - 0.010000 : 6078892 [20081216-15:22:08.801767465] [20081216-15:22:08.803973205] [ close] 0.002000 0.006440 0.014000 698 [20081216-15:22:08.806077946] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081216-15:22:08.808316752] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081216-15:22:08.810522662] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081216-15:22:08.812794436] msec_range[3] 500.000000 - 1000.000000 : 0 [20081216-15:22:08.815025381] msec_range[4] 200.000000 - 500.000000 : 0 [20081216-15:22:08.817393227] msec_range[5] 100.000000 - 200.000000 : 0 [20081216-15:22:08.819635225] msec_range[6] 50.000000 - 100.000000 : 0 [20081216-15:22:08.822125219] msec_range[7] 20.000000 - 50.000000 : 0 [20081216-15:22:08.824370524] msec_range[8] 10.000000 - 20.000000 : 0 [20081216-15:22:08.826678811] msec_range[9] 5.000000 - 10.000000 : 0 [20081216-15:22:08.828801217] msec_range[10] 2.000000 - 5.000000 : 0 [20081216-15:22:08.830968293] msec_range[11] 1.000000 - 2.000000 : 0 [20081216-15:22:08.833124007] msec_range[12] 0.500000 - 1.000000 : 0 [20081216-15:22:08.835533875] msec_range[13] 0.200000 - 0.500000 : 0 [20081216-15:22:08.838014076] msec_range[14] 0.100000 - 0.200000 : 0 [20081216-15:22:08.840300693] msec_range[15] 0.050000 - 0.100000 : 0 [20081216-15:22:08.842628302] msec_range[16] 0.020000 - 0.050000 : 0 [20081216-15:22:08.844945271] msec_range[17] 0.010000 - 0.020000 : 31 [20081216-15:22:08.847213266] msec_range[18] 0.000000 - 0.010000 : 667 [20081216-15:22:08.849591096] [20081216-15:22:08.851971856] [20081216-15:22:08.854583816] [20081216-15:22:08.856815964] [20081216-15:22:08.859298372] 1.2% User Time [20081216-15:22:08.861972369] 13.5% System Time [20081216-15:22:08.864592305] 14.8% CPU Utilization [20081216-15:22:08.866938167] Profilers reporting [20081216-15:22:08.869721214] /autobench/scripts/doprofilers: line 33: 23950 Terminated ${CMDS[$i]} [20081216-15:22:08.881933582] /autobench/scripts/doprofilers: line 33: 23967 Terminated ${CMDS[$i]} [20081216-15:22:08.907250503] /autobench/scripts/doprofilers: line 33: 23994 Terminated ${CMDS[$i]} [20081216-15:22:21.613778320] Profilers postprocessing [20081216-15:22:21.903374595] Processing File : iostat.001 [20081216-15:22:21.905683622] Discovered iostat_interval=[5] [20081216-15:22:22.513955650] Processing Directory : sar.breakout.001 [20081216-15:22:22.516090795] Discovered sar_interval=[5] [20081216-15:22:22.678759606] Processing File : mpstat.001 [20081216-15:22:22.681048316] Discovered mpstat_interval=[5] [20081216-15:22:23.812923133] Stopping profiling. [20081216-15:22:23.818291147] Killing daemon. [20081216-15:22:26.080706195] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0008.08-12-16_15.16.55/analysis/oprofile.001 [20081216-15:22:26.082856535] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0008.08-12-16_15.16.55/analysis/oprofile-brief.001 [20081216-15:22:27.631515548] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-16_1503/ext3-baseline' [20081216-15:22:29.626387770] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081216-15:22:30.159920517] PROCESSING COMMAND : 'mount -t ext3 /dev/ffsbdev1 /mnt/ffsb1' [20081216-15:22:30.306925764] PROCESSING COMMAND : 'run sequential_reads__threads_0032 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb num_threads=32' [20081216-15:22:30.351830816] new log requested [20081216-15:22:30.374043862] Running command ffsb [20081216-15:22:38.709381140] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb [20081216-15:22:38.722854882] Importing argument : num_threads=32 [20081216-15:22:38.748749158] Found a ext3 filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081216-15:22:38.824256706] FFSB version 6.0-RC2 started [20081216-15:22:38.826445557] [20081216-15:22:38.945980094] benchmark time = 300 [20081216-15:22:38.948194022] ThreadGroup 0 [20081216-15:22:38.950299310] ================ [20081216-15:22:38.952372292] num_threads = 32 [20081216-15:22:38.954158105] [20081216-15:22:38.955984554] read_random = off [20081216-15:22:38.957783638] read_size = 0 (0B) [20081216-15:22:38.959614248] read_blocksize = 4096 (4KB) [20081216-15:22:38.961366468] read_skip = off [20081216-15:22:38.963176333] read_skipsize = 0 (0B) [20081216-15:22:38.964958979] [20081216-15:22:38.966770833] write_random = off [20081216-15:22:38.968523337] write_size = 0 (0B) [20081216-15:22:38.970345289] fsync_file = 0 [20081216-15:22:38.972086742] write_blocksize = 0 (0B) [20081216-15:22:38.973890331] wait time = 0 [20081216-15:22:38.975622060] [20081216-15:22:38.977437274] op weights [20081216-15:22:38.979186414] read = 0 (0.00%) [20081216-15:22:38.981011431] readall = 1 (100.00%) [20081216-15:22:38.982751070] write = 0 (0.00%) [20081216-15:22:38.984554943] create = 0 (0.00%) [20081216-15:22:38.986325773] append = 0 (0.00%) [20081216-15:22:38.988119926] delete = 0 (0.00%) [20081216-15:22:38.989915583] metaop = 0 (0.00%) [20081216-15:22:38.991752020] createdir = 0 (0.00%) [20081216-15:22:38.993966080] stat = 0 (0.00%) [20081216-15:22:38.996060115] writeall = 0 (0.00%) [20081216-15:22:38.998107465] writeall_fsync = 0 (0.00%) [20081216-15:22:38.999949554] open_close = 0 (0.00%) [20081216-15:22:39.001852475] write_fsync = 0 (0.00%) [20081216-15:22:39.003703720] create_fsync = 0 (0.00%) [20081216-15:22:39.005477606] append_fsync = 0 (0.00%) [20081216-15:22:39.007318171] [20081216-15:22:39.009066538] FileSystem /mnt/ffsb1 [20081216-15:22:39.010916072] ========== [20081216-15:22:39.012703685] num_dirs = 0 [20081216-15:22:39.014500151] starting files = 1024 [20081216-15:22:39.016227336] [20081216-15:22:39.018050787] min file size = 36700160 (35MB) [20081216-15:22:39.019818786] max file size = 36700160 (35MB) [20081216-15:22:39.021615337] directio = off [20081216-15:22:39.023342661] alignedio = on [20081216-15:22:39.025140810] bufferedio = off [20081216-15:22:39.026890379] [20081216-15:22:39.028705159] aging is off [20081216-15:22:39.030428943] current utilization = 52.33% [20081216-15:22:39.032229254] [20081216-15:22:39.033975437] checking existing fs: /mnt/ffsb1 [20081216-15:22:39.151477146] fs setup took 0 secs [20081216-15:22:39.806726911] Syncing()...0 sec [20081216-15:22:39.808726350] Starting Actual Benchmark At: Tue Dec 16 15:22:39 2008 [20081216-15:22:39.821621894] [20081216-15:27:48.070192224] Syncing()...0 sec [20081216-15:27:48.105400092] FFSB benchmark finished at: Tue Dec 16 15:27:47 2008 [20081216-15:27:48.108217019] [20081216-15:27:48.110926713] Results: [20081216-15:27:48.190524811] Benchmark took 308.01 sec [20081216-15:27:48.193252647] [20081216-15:27:48.195905309] Total Results [20081216-15:27:48.210908530] =============== [20081216-15:27:48.213469513] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081216-15:27:48.215835251] ======= ============ ========= ======= =========== ========== [20081216-15:27:48.218225508] readall : 6307840 20479.64 100.000% 100.000% 80MB/sec [20081216-15:27:48.220418406] - [20081216-15:27:48.222917311] 20479.64 Transactions per Second [20081216-15:27:48.225299774] [20081216-15:27:48.227698254] Throughput Results [20081216-15:27:48.242571030] =================== [20081216-15:27:48.244665475] Read Throughput: 80MB/sec [20081216-15:27:48.247148273] [20081216-15:27:48.249422814] System Call Latency statistics in millisecs [20081216-15:27:48.251516134] ===== [20081216-15:27:48.254083305] Min Avg Max Total Calls [20081216-15:27:48.256397077] ======== ======== ======== ============ [20081216-15:27:48.258632540] [ open] 0.006000 20.935722 931.945984 704 [20081216-15:27:48.260757590] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081216-15:27:48.263070219] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081216-15:27:48.265523406] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081216-15:27:48.267730401] msec_range[3] 500.000000 - 1000.000000 : 6 [20081216-15:27:48.269795504] msec_range[4] 200.000000 - 500.000000 : 32 [20081216-15:27:48.272172812] msec_range[5] 100.000000 - 200.000000 : 3 [20081216-15:27:48.274340345] msec_range[6] 50.000000 - 100.000000 : 1 [20081216-15:27:48.276475703] msec_range[7] 20.000000 - 50.000000 : 0 [20081216-15:27:48.278544281] msec_range[8] 10.000000 - 20.000000 : 0 [20081216-15:27:48.280962064] msec_range[9] 5.000000 - 10.000000 : 0 [20081216-15:27:48.283336950] msec_range[10] 2.000000 - 5.000000 : 2 [20081216-15:27:48.285675940] msec_range[11] 1.000000 - 2.000000 : 1 [20081216-15:27:48.287952090] msec_range[12] 0.500000 - 1.000000 : 2 [20081216-15:27:48.290315142] msec_range[13] 0.200000 - 0.500000 : 0 [20081216-15:27:48.327900235] msec_range[14] 0.100000 - 0.200000 : 6 [20081216-15:27:48.330252136] msec_range[15] 0.050000 - 0.100000 : 65 [20081216-15:27:48.332545476] msec_range[16] 0.020000 - 0.050000 : 439 [20081216-15:27:48.335093867] msec_range[17] 0.010000 - 0.020000 : 125 [20081216-15:27:48.337369721] msec_range[18] 0.000000 - 0.010000 : 22 [20081216-15:27:48.339809655] [20081216-15:27:48.342015063] [ read] 0.001000 1.543446 2929.322998 6307840 [20081216-15:27:48.345739034] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081216-15:27:48.348322887] msec_range[1] 2000.000000 - 5000.000000 : 50 [20081216-15:27:48.350765584] msec_range[2] 1000.000000 - 2000.000000 : 1200 [20081216-15:27:48.353116471] msec_range[3] 500.000000 - 1000.000000 : 4898 [20081216-15:27:48.355626970] msec_range[4] 200.000000 - 500.000000 : 12399 [20081216-15:27:48.357805100] msec_range[5] 100.000000 - 200.000000 : 724 [20081216-15:27:48.360094839] msec_range[6] 50.000000 - 100.000000 : 350 [20081216-15:27:48.362261428] msec_range[7] 20.000000 - 50.000000 : 372 [20081216-15:27:48.364534060] msec_range[8] 10.000000 - 20.000000 : 283 [20081216-15:27:48.366816716] msec_range[9] 5.000000 - 10.000000 : 4127 [20081216-15:27:48.368990761] msec_range[10] 2.000000 - 5.000000 : 18935 [20081216-15:27:48.371109656] msec_range[11] 1.000000 - 2.000000 : 269 [20081216-15:27:48.373453215] msec_range[12] 0.500000 - 1.000000 : 582 [20081216-15:27:48.375927181] msec_range[13] 0.200000 - 0.500000 : 5452 [20081216-15:27:48.378557203] msec_range[14] 0.100000 - 0.200000 : 698 [20081216-15:27:48.380948904] msec_range[15] 0.050000 - 0.100000 : 1416 [20081216-15:27:48.383616482] msec_range[16] 0.020000 - 0.050000 : 10445 [20081216-15:27:48.386000101] msec_range[17] 0.010000 - 0.020000 : 169708 [20081216-15:27:48.388178680] msec_range[18] 0.000000 - 0.010000 : 6075932 [20081216-15:27:48.390660914] [20081216-15:27:48.392946487] [ close] 0.002000 0.006358 0.024000 704 [20081216-15:27:48.395137279] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081216-15:27:48.397257403] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081216-15:27:48.399797042] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081216-15:27:48.401984350] msec_range[3] 500.000000 - 1000.000000 : 0 [20081216-15:27:48.404170232] msec_range[4] 200.000000 - 500.000000 : 0 [20081216-15:27:48.406348998] msec_range[5] 100.000000 - 200.000000 : 0 [20081216-15:27:48.408713741] msec_range[6] 50.000000 - 100.000000 : 0 [20081216-15:27:48.411041983] msec_range[7] 20.000000 - 50.000000 : 0 [20081216-15:27:48.414237547] msec_range[8] 10.000000 - 20.000000 : 0 [20081216-15:27:48.416605682] msec_range[9] 5.000000 - 10.000000 : 0 [20081216-15:27:48.419112721] msec_range[10] 2.000000 - 5.000000 : 0 [20081216-15:27:48.421455167] msec_range[11] 1.000000 - 2.000000 : 0 [20081216-15:27:48.423814705] msec_range[12] 0.500000 - 1.000000 : 0 [20081216-15:27:48.426240111] msec_range[13] 0.200000 - 0.500000 : 0 [20081216-15:27:48.428410661] msec_range[14] 0.100000 - 0.200000 : 0 [20081216-15:27:48.430880791] msec_range[15] 0.050000 - 0.100000 : 0 [20081216-15:27:48.433264331] msec_range[16] 0.020000 - 0.050000 : 1 [20081216-15:27:48.435764059] msec_range[17] 0.010000 - 0.020000 : 31 [20081216-15:27:48.438137794] msec_range[18] 0.000000 - 0.010000 : 672 [20081216-15:27:48.440569916] [20081216-15:27:48.442820308] [20081216-15:27:48.444971169] [20081216-15:27:48.447062843] [20081216-15:27:48.449229115] 1.2% User Time [20081216-15:27:48.451283754] 14.6% System Time [20081216-15:27:48.453422058] 15.9% CPU Utilization [20081216-15:27:48.455495948] Profilers reporting [20081216-15:27:48.596835118] /autobench/scripts/doprofilers: line 33: 29795 Terminated ${CMDS[$i]} [20081216-15:27:48.624322317] /autobench/scripts/doprofilers: line 33: 29801 Terminated ${CMDS[$i]} [20081216-15:27:48.649455431] /autobench/scripts/doprofilers: line 33: 29824 Terminated ${CMDS[$i]} [20081216-15:27:59.898873365] Profilers postprocessing [20081216-15:28:00.178393912] Processing File : iostat.001 [20081216-15:28:00.180935174] Discovered iostat_interval=[5] [20081216-15:28:00.754811271] Processing Directory : sar.breakout.001 [20081216-15:28:00.757062845] Discovered sar_interval=[5] [20081216-15:28:00.921911866] Processing File : mpstat.001 [20081216-15:28:00.924573230] Discovered mpstat_interval=[5] [20081216-15:28:02.057343287] Stopping profiling. [20081216-15:28:02.062387186] Killing daemon. [20081216-15:28:03.540633182] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0032.08-12-16_15.22.30/analysis/oprofile.001 [20081216-15:28:03.542838069] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0032.08-12-16_15.22.30/analysis/oprofile-brief.001 [20081216-15:28:05.103581714] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-16_1503/ext3-baseline' [20081216-15:28:07.200835161] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081216-15:28:07.830729243] PROCESSING COMMAND : 'mount -t ext3 /dev/ffsbdev1 /mnt/ffsb1' [20081216-15:28:07.917459062] PROCESSING COMMAND : 'run random_reads__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb num_threads=1' [20081216-15:28:07.978512970] new log requested [20081216-15:28:08.001525252] Running command ffsb [20081216-15:28:16.095436993] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb [20081216-15:28:16.116668055] Importing argument : num_threads=1 [20081216-15:28:16.142626645] Found a ext3 filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081216-15:28:16.220605363] FFSB version 6.0-RC2 started [20081216-15:28:16.222801746] [20081216-15:28:16.225028701] benchmark time = 300 [20081216-15:28:16.226968125] ThreadGroup 0 [20081216-15:28:16.229129507] ================ [20081216-15:28:16.230991066] num_threads = 1 [20081216-15:28:16.232916413] [20081216-15:28:16.234835042] read_random = on [20081216-15:28:16.236930141] read_size = 1048576 (1MB) [20081216-15:28:16.238803828] read_blocksize = 4096 (4KB) [20081216-15:28:16.240626682] read_skip = off [20081216-15:28:16.242395966] read_skipsize = 0 (0B) [20081216-15:28:16.244260729] [20081216-15:28:16.246039128] write_random = off [20081216-15:28:16.247859686] write_size = 0 (0B) [20081216-15:28:16.249618643] fsync_file = 0 [20081216-15:28:16.251436959] write_blocksize = 0 (0B) [20081216-15:28:16.253212441] wait time = 0 [20081216-15:28:16.255041011] [20081216-15:28:16.256919101] op weights [20081216-15:28:16.258689089] read = 1 (100.00%) [20081216-15:28:16.260561400] readall = 0 (0.00%) [20081216-15:28:16.262341059] write = 0 (0.00%) [20081216-15:28:16.264212018] create = 0 (0.00%) [20081216-15:28:16.265970240] append = 0 (0.00%) [20081216-15:28:16.267837308] delete = 0 (0.00%) [20081216-15:28:16.269703501] metaop = 0 (0.00%) [20081216-15:28:16.271473241] createdir = 0 (0.00%) [20081216-15:28:16.273311840] stat = 0 (0.00%) [20081216-15:28:16.275160066] writeall = 0 (0.00%) [20081216-15:28:16.276924550] writeall_fsync = 0 (0.00%) [20081216-15:28:16.278761040] open_close = 0 (0.00%) [20081216-15:28:16.280601831] write_fsync = 0 (0.00%) [20081216-15:28:16.282341618] create_fsync = 0 (0.00%) [20081216-15:28:16.284152101] append_fsync = 0 (0.00%) [20081216-15:28:16.285894713] [20081216-15:28:16.287764149] FileSystem /mnt/ffsb1 [20081216-15:28:16.289571067] ========== [20081216-15:28:16.291401799] num_dirs = 0 [20081216-15:28:16.293252268] starting files = 1024 [20081216-15:28:16.295160401] [20081216-15:28:16.297070841] min file size = 36700160 (35MB) [20081216-15:28:16.298881612] max file size = 36700160 (35MB) [20081216-15:28:16.300755792] directio = off [20081216-15:28:16.302561126] alignedio = on [20081216-15:28:16.304386308] bufferedio = off [20081216-15:28:16.306131236] [20081216-15:28:16.307949021] aging is off [20081216-15:28:16.309761945] current utilization = 52.33% [20081216-15:28:16.311597681] [20081216-15:28:16.313452926] checking existing fs: /mnt/ffsb1 [20081216-15:28:16.341889321] fs setup took 0 secs [20081216-15:28:17.086342905] Syncing()...0 sec [20081216-15:28:17.088388614] Starting Actual Benchmark At: Tue Dec 16 15:28:17 2008 [20081216-15:28:17.101186575] [20081216-15:33:18.513096012] Syncing()...0 sec [20081216-15:33:18.516077894] FFSB benchmark finished at: Tue Dec 16 15:33:18 2008 [20081216-15:33:18.518931680] [20081216-15:33:18.521784984] Results: [20081216-15:33:18.537300790] Benchmark took 301.43 sec [20081216-15:33:18.540027628] [20081216-15:33:18.542451751] Total Results [20081216-15:33:18.557968810] =============== [20081216-15:33:18.560811161] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081216-15:33:18.563735024] ======= ============ ========= ======= =========== ========== [20081216-15:33:18.566045599] read : 100864 334.62 100.000% 100.000% 1.31MB/sec [20081216-15:33:18.570496730] - [20081216-15:33:18.574830629] 334.62 Transactions per Second [20081216-15:33:18.577587370] [20081216-15:33:18.581671106] Throughput Results [20081216-15:33:18.597772524] =================== [20081216-15:33:18.600637342] Read Throughput: 1.31MB/sec [20081216-15:33:18.603191194] [20081216-15:33:18.605653639] System Call Latency statistics in millisecs [20081216-15:33:18.608295654] ===== [20081216-15:33:18.611170478] Min Avg Max Total Calls [20081216-15:33:18.614120166] ======== ======== ======== ============ [20081216-15:33:18.616700109] [ open] 0.009000 0.016302 0.031000 394 [20081216-15:33:18.619708212] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081216-15:33:18.622190641] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081216-15:33:18.624821610] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081216-15:33:18.627058825] msec_range[3] 500.000000 - 1000.000000 : 0 [20081216-15:33:18.629494405] msec_range[4] 200.000000 - 500.000000 : 0 [20081216-15:33:18.632425234] msec_range[5] 100.000000 - 200.000000 : 0 [20081216-15:33:18.635846018] msec_range[6] 50.000000 - 100.000000 : 0 [20081216-15:33:18.638245906] msec_range[7] 20.000000 - 50.000000 : 0 [20081216-15:33:18.640512111] msec_range[8] 10.000000 - 20.000000 : 0 [20081216-15:33:18.643240651] msec_range[9] 5.000000 - 10.000000 : 0 [20081216-15:33:18.645925963] msec_range[10] 2.000000 - 5.000000 : 0 [20081216-15:33:18.648587703] msec_range[11] 1.000000 - 2.000000 : 0 [20081216-15:33:18.651159502] msec_range[12] 0.500000 - 1.000000 : 0 [20081216-15:33:18.653546924] msec_range[13] 0.200000 - 0.500000 : 0 [20081216-15:33:18.655947982] msec_range[14] 0.100000 - 0.200000 : 0 [20081216-15:33:18.658512354] msec_range[15] 0.050000 - 0.100000 : 0 [20081216-15:33:18.660941993] msec_range[16] 0.020000 - 0.050000 : 91 [20081216-15:33:18.663346800] msec_range[17] 0.010000 - 0.020000 : 301 [20081216-15:33:18.671483756] msec_range[18] 0.000000 - 0.010000 : 2 [20081216-15:33:18.674683087] [20081216-15:33:18.677415135] [ read] 0.002000 2.982789 40.624001 100864 [20081216-15:33:18.680004074] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081216-15:33:18.682778958] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081216-15:33:18.685622642] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081216-15:33:18.688380874] msec_range[3] 500.000000 - 1000.000000 : 0 [20081216-15:33:18.691240193] msec_range[4] 200.000000 - 500.000000 : 0 [20081216-15:33:18.694055242] msec_range[5] 100.000000 - 200.000000 : 0 [20081216-15:33:18.697675699] msec_range[6] 50.000000 - 100.000000 : 0 [20081216-15:33:18.700480723] msec_range[7] 20.000000 - 50.000000 : 29 [20081216-15:33:18.703344078] msec_range[8] 10.000000 - 20.000000 : 2203 [20081216-15:33:18.705965762] msec_range[9] 5.000000 - 10.000000 : 2459 [20081216-15:33:18.708680953] msec_range[10] 2.000000 - 5.000000 : 62387 [20081216-15:33:18.711146931] msec_range[11] 1.000000 - 2.000000 : 20192 [20081216-15:33:18.713606303] msec_range[12] 0.500000 - 1.000000 : 536 [20081216-15:33:18.716230455] msec_range[13] 0.200000 - 0.500000 : 10346 [20081216-15:33:18.719001753] msec_range[14] 0.100000 - 0.200000 : 235 [20081216-15:33:18.721971984] msec_range[15] 0.050000 - 0.100000 : 0 [20081216-15:33:18.724611365] msec_range[16] 0.020000 - 0.050000 : 2 [20081216-15:33:18.727258569] msec_range[17] 0.010000 - 0.020000 : 235 [20081216-15:33:18.729734274] msec_range[18] 0.000000 - 0.010000 : 2240 [20081216-15:33:18.733015532] [20081216-15:33:18.735632352] [ lseek] 0.000000 0.001170 0.021000 100864 [20081216-15:33:18.738757436] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081216-15:33:18.741317153] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081216-15:33:18.744061280] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081216-15:33:18.746609216] msec_range[3] 500.000000 - 1000.000000 : 0 [20081216-15:33:18.749385808] msec_range[4] 200.000000 - 500.000000 : 0 [20081216-15:33:18.752053363] msec_range[5] 100.000000 - 200.000000 : 0 [20081216-15:33:18.754647120] msec_range[6] 50.000000 - 100.000000 : 0 [20081216-15:33:18.758917808] msec_range[7] 20.000000 - 50.000000 : 0 [20081216-15:33:18.762273925] msec_range[8] 10.000000 - 20.000000 : 0 [20081216-15:33:18.765244224] msec_range[9] 5.000000 - 10.000000 : 0 [20081216-15:33:18.767974989] msec_range[10] 2.000000 - 5.000000 : 0 [20081216-15:33:18.770701576] msec_range[11] 1.000000 - 2.000000 : 0 [20081216-15:33:18.773107123] msec_range[12] 0.500000 - 1.000000 : 0 [20081216-15:33:18.775602729] msec_range[13] 0.200000 - 0.500000 : 0 [20081216-15:33:18.778824692] msec_range[14] 0.100000 - 0.200000 : 0 [20081216-15:33:18.781311040] msec_range[15] 0.050000 - 0.100000 : 0 [20081216-15:33:18.783782665] msec_range[16] 0.020000 - 0.050000 : 1 [20081216-15:33:18.786301767] msec_range[17] 0.010000 - 0.020000 : 14 [20081216-15:33:18.788925947] msec_range[18] 0.000000 - 0.010000 : 100849 [20081216-15:33:18.791237265] [20081216-15:33:18.793619502] [ close] 0.002000 0.004675 0.010000 394 [20081216-15:33:18.796124714] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081216-15:33:18.798856743] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081216-15:33:18.801633698] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081216-15:33:18.804008073] msec_range[3] 500.000000 - 1000.000000 : 0 [20081216-15:33:18.806351910] msec_range[4] 200.000000 - 500.000000 : 0 [20081216-15:33:18.808746946] msec_range[5] 100.000000 - 200.000000 : 0 [20081216-15:33:18.811419294] msec_range[6] 50.000000 - 100.000000 : 0 [20081216-15:33:18.814008951] msec_range[7] 20.000000 - 50.000000 : 0 [20081216-15:33:18.816246184] msec_range[8] 10.000000 - 20.000000 : 0 [20081216-15:33:18.818679982] msec_range[9] 5.000000 - 10.000000 : 0 [20081216-15:33:18.821372201] msec_range[10] 2.000000 - 5.000000 : 0 [20081216-15:33:18.823961756] msec_range[11] 1.000000 - 2.000000 : 0 [20081216-15:33:18.826307159] msec_range[12] 0.500000 - 1.000000 : 0 [20081216-15:33:18.828538252] msec_range[13] 0.200000 - 0.500000 : 0 [20081216-15:33:18.830979522] msec_range[14] 0.100000 - 0.200000 : 0 [20081216-15:33:18.833409652] msec_range[15] 0.050000 - 0.100000 : 0 [20081216-15:33:18.835702334] msec_range[16] 0.020000 - 0.050000 : 0 [20081216-15:33:18.838093969] msec_range[17] 0.010000 - 0.020000 : 3 [20081216-15:33:18.840369982] msec_range[18] 0.000000 - 0.010000 : 391 [20081216-15:33:18.842601368] [20081216-15:33:18.844741244] [20081216-15:33:18.846960024] [20081216-15:33:18.849138336] [20081216-15:33:18.851205071] 0.1% User Time [20081216-15:33:18.853407969] 0.9% System Time [20081216-15:33:18.855578696] 1.0% CPU Utilization [20081216-15:33:18.857641142] Profilers reporting [20081216-15:33:18.859816228] /autobench/scripts/doprofilers: line 33: 3116 Terminated ${CMDS[$i]} [20081216-15:33:18.861989636] /autobench/scripts/doprofilers: line 33: 3118 Terminated ${CMDS[$i]} [20081216-15:33:18.864054561] /autobench/scripts/doprofilers: line 33: 3152 Terminated ${CMDS[$i]} [20081216-15:33:25.970220579] Profilers postprocessing [20081216-15:33:26.055765049] Processing File : iostat.001 [20081216-15:33:26.057993324] Discovered iostat_interval=[5] [20081216-15:33:26.584326340] Processing Directory : sar.breakout.001 [20081216-15:33:26.586490856] Discovered sar_interval=[5] [20081216-15:33:26.748044127] Processing File : mpstat.001 [20081216-15:33:26.750261976] Discovered mpstat_interval=[5] [20081216-15:33:27.884152197] Stopping profiling. [20081216-15:33:27.890347121] Killing daemon. [20081216-15:33:29.050737239] Processing File : /autobench/logs/ffsb.random_reads__threads_0001.08-12-16_15.28.07/analysis/oprofile.001 [20081216-15:33:29.053112301] Processing File : /autobench/logs/ffsb.random_reads__threads_0001.08-12-16_15.28.07/analysis/oprofile-brief.001 [20081216-15:33:29.964035503] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-16_1503/ext3-baseline' [20081216-15:33:31.219452357] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081216-15:33:31.488897296] PROCESSING COMMAND : 'mount -t ext3 /dev/ffsbdev1 /mnt/ffsb1' [20081216-15:33:31.632302038] PROCESSING COMMAND : 'run random_reads__threads_0008 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb num_threads=8' [20081216-15:33:31.700957066] new log requested [20081216-15:33:31.723911909] Running command ffsb [20081216-15:33:39.021013877] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb [20081216-15:33:39.033980914] Importing argument : num_threads=8 [20081216-15:33:39.060861422] Found a ext3 filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081216-15:33:39.125746508] FFSB version 6.0-RC2 started [20081216-15:33:39.127940598] [20081216-15:33:39.157038318] benchmark time = 300 [20081216-15:33:39.159283472] ThreadGroup 0 [20081216-15:33:39.161173400] ================ [20081216-15:33:39.163277021] num_threads = 8 [20081216-15:33:39.165164809] [20081216-15:33:39.166977267] read_random = on [20081216-15:33:39.168737282] read_size = 1048576 (1MB) [20081216-15:33:39.170583407] read_blocksize = 4096 (4KB) [20081216-15:33:39.172332867] read_skip = off [20081216-15:33:39.174110721] read_skipsize = 0 (0B) [20081216-15:33:39.175854203] [20081216-15:33:39.177701795] write_random = off [20081216-15:33:39.179461556] write_size = 0 (0B) [20081216-15:33:39.181246970] fsync_file = 0 [20081216-15:33:39.182933083] write_blocksize = 0 (0B) [20081216-15:33:39.184857399] wait time = 0 [20081216-15:33:39.186575190] [20081216-15:33:39.188357886] op weights [20081216-15:33:39.190090264] read = 1 (100.00%) [20081216-15:33:39.191950575] readall = 0 (0.00%) [20081216-15:33:39.193651868] write = 0 (0.00%) [20081216-15:33:39.195475082] create = 0 (0.00%) [20081216-15:33:39.197208784] append = 0 (0.00%) [20081216-15:33:39.199129464] delete = 0 (0.00%) [20081216-15:33:39.200942876] metaop = 0 (0.00%) [20081216-15:33:39.202748449] createdir = 0 (0.00%) [20081216-15:33:39.204479879] stat = 0 (0.00%) [20081216-15:33:39.206316784] writeall = 0 (0.00%) [20081216-15:33:39.208140375] writeall_fsync = 0 (0.00%) [20081216-15:33:39.209898942] open_close = 0 (0.00%) [20081216-15:33:39.211731236] write_fsync = 0 (0.00%) [20081216-15:33:39.213532171] create_fsync = 0 (0.00%) [20081216-15:33:39.215258245] append_fsync = 0 (0.00%) [20081216-15:33:39.217065891] [20081216-15:33:39.218915203] FileSystem /mnt/ffsb1 [20081216-15:33:39.220625083] ========== [20081216-15:33:39.222455637] num_dirs = 0 [20081216-15:33:39.224255155] starting files = 1024 [20081216-15:33:39.225907711] [20081216-15:33:39.227795114] min file size = 36700160 (35MB) [20081216-15:33:39.229598454] max file size = 36700160 (35MB) [20081216-15:33:39.231403140] directio = off [20081216-15:33:39.233123409] alignedio = on [20081216-15:33:39.234978749] bufferedio = off [20081216-15:33:39.236681339] [20081216-15:33:39.238523509] aging is off [20081216-15:33:39.240261765] current utilization = 52.33% [20081216-15:33:39.242133666] [20081216-15:33:39.243943040] checking existing fs: /mnt/ffsb1 [20081216-15:33:39.282226557] fs setup took 0 secs [20081216-15:33:40.056073398] Syncing()...0 sec [20081216-15:33:40.058051660] Starting Actual Benchmark At: Tue Dec 16 15:33:40 2008 [20081216-15:33:40.070992937] [20081216-15:38:42.672101448] Syncing()...0 sec [20081216-15:38:42.675060906] FFSB benchmark finished at: Tue Dec 16 15:38:42 2008 [20081216-15:38:42.677870551] [20081216-15:38:42.680575141] Results: [20081216-15:38:42.695903982] Benchmark took 302.62 sec [20081216-15:38:42.698672869] [20081216-15:38:42.701213326] Total Results [20081216-15:38:42.717277715] =============== [20081216-15:38:42.720613821] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081216-15:38:42.723463587] ======= ============ ========= ======= =========== ========== [20081216-15:38:42.726429081] read : 119552 395.06 100.000% 100.000% 1.54MB/sec [20081216-15:38:42.729305815] - [20081216-15:38:42.732609416] 395.06 Transactions per Second [20081216-15:38:42.734980259] [20081216-15:38:42.738691869] Throughput Results [20081216-15:38:42.754915083] =================== [20081216-15:38:42.757859783] Read Throughput: 1.54MB/sec [20081216-15:38:42.760534176] [20081216-15:38:42.765581825] System Call Latency statistics in millisecs [20081216-15:38:42.768302673] ===== [20081216-15:38:42.770844236] Min Avg Max Total Calls [20081216-15:38:42.773629450] ======== ======== ======== ============ [20081216-15:38:42.776201702] [ open] 0.006000 0.016201 0.314000 467 [20081216-15:38:42.778851604] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081216-15:38:42.785155165] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081216-15:38:42.788524837] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081216-15:38:42.792184314] msec_range[3] 500.000000 - 1000.000000 : 0 [20081216-15:38:42.795687159] msec_range[4] 200.000000 - 500.000000 : 0 [20081216-15:38:42.798526279] msec_range[5] 100.000000 - 200.000000 : 0 [20081216-15:38:42.801066536] msec_range[6] 50.000000 - 100.000000 : 0 [20081216-15:38:42.803934389] msec_range[7] 20.000000 - 50.000000 : 0 [20081216-15:38:42.807586344] msec_range[8] 10.000000 - 20.000000 : 0 [20081216-15:38:42.809901973] msec_range[9] 5.000000 - 10.000000 : 0 [20081216-15:38:42.812016453] msec_range[10] 2.000000 - 5.000000 : 0 [20081216-15:38:42.814031958] msec_range[11] 1.000000 - 2.000000 : 0 [20081216-15:38:42.816997497] msec_range[12] 0.500000 - 1.000000 : 0 [20081216-15:38:42.819581684] msec_range[13] 0.200000 - 0.500000 : 1 [20081216-15:38:42.822279242] msec_range[14] 0.100000 - 0.200000 : 0 [20081216-15:38:42.830193375] msec_range[15] 0.050000 - 0.100000 : 0 [20081216-15:38:42.833211668] msec_range[16] 0.020000 - 0.050000 : 120 [20081216-15:38:42.836213091] msec_range[17] 0.010000 - 0.020000 : 266 [20081216-15:38:42.839411836] msec_range[18] 0.000000 - 0.010000 : 80 [20081216-15:38:42.843344871] [20081216-15:38:42.845794623] [ read] 0.002000 20.162213 763.138000 119552 [20081216-15:38:42.848440182] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081216-15:38:42.852235423] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081216-15:38:42.855443077] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081216-15:38:42.858042361] msec_range[3] 500.000000 - 1000.000000 : 10 [20081216-15:38:42.860904860] msec_range[4] 200.000000 - 500.000000 : 619 [20081216-15:38:42.863218096] msec_range[5] 100.000000 - 200.000000 : 3388 [20081216-15:38:42.865340293] msec_range[6] 50.000000 - 100.000000 : 8864 [20081216-15:38:42.868770623] msec_range[7] 20.000000 - 50.000000 : 20198 [20081216-15:38:42.871277488] msec_range[8] 10.000000 - 20.000000 : 18794 [20081216-15:38:42.873904388] msec_range[9] 5.000000 - 10.000000 : 18715 [20081216-15:38:42.876457982] msec_range[10] 2.000000 - 5.000000 : 32540 [20081216-15:38:42.878810342] msec_range[11] 1.000000 - 2.000000 : 13124 [20081216-15:38:42.881313986] msec_range[12] 0.500000 - 1.000000 : 468 [20081216-15:38:42.884388266] msec_range[13] 0.200000 - 0.500000 : 388 [20081216-15:38:42.887800961] msec_range[14] 0.100000 - 0.200000 : 4 [20081216-15:38:42.890955838] msec_range[15] 0.050000 - 0.100000 : 0 [20081216-15:38:42.893590156] msec_range[16] 0.020000 - 0.050000 : 0 [20081216-15:38:42.896148282] msec_range[17] 0.010000 - 0.020000 : 399 [20081216-15:38:42.898771538] msec_range[18] 0.000000 - 0.010000 : 2041 [20081216-15:38:42.901151164] [20081216-15:38:42.903743045] [ lseek] 0.000000 0.001185 0.036000 119552 [20081216-15:38:42.906774920] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081216-15:38:42.909572677] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081216-15:38:42.912236156] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081216-15:38:42.914998040] msec_range[3] 500.000000 - 1000.000000 : 0 [20081216-15:38:42.917878795] msec_range[4] 200.000000 - 500.000000 : 0 [20081216-15:38:42.921320864] msec_range[5] 100.000000 - 200.000000 : 0 [20081216-15:38:42.924080272] msec_range[6] 50.000000 - 100.000000 : 0 [20081216-15:38:42.926681838] msec_range[7] 20.000000 - 50.000000 : 0 [20081216-15:38:42.931001853] msec_range[8] 10.000000 - 20.000000 : 0 [20081216-15:38:42.934122063] msec_range[9] 5.000000 - 10.000000 : 0 [20081216-15:38:42.936481788] msec_range[10] 2.000000 - 5.000000 : 0 [20081216-15:38:42.938925476] msec_range[11] 1.000000 - 2.000000 : 0 [20081216-15:38:42.941405515] msec_range[12] 0.500000 - 1.000000 : 0 [20081216-15:38:42.945887375] msec_range[13] 0.200000 - 0.500000 : 0 [20081216-15:38:42.948566741] msec_range[14] 0.100000 - 0.200000 : 0 [20081216-15:38:42.951794487] msec_range[15] 0.050000 - 0.100000 : 0 [20081216-15:38:42.954260240] msec_range[16] 0.020000 - 0.050000 : 4 [20081216-15:38:42.956477540] msec_range[17] 0.010000 - 0.020000 : 23 [20081216-15:38:42.958834027] msec_range[18] 0.000000 - 0.010000 : 119525 [20081216-15:38:42.961366624] [20081216-15:38:42.965430227] [ close] 0.002000 0.004587 0.019000 467 [20081216-15:38:42.967898651] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081216-15:38:42.970478430] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081216-15:38:42.973238093] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081216-15:38:42.975606049] msec_range[3] 500.000000 - 1000.000000 : 0 [20081216-15:38:42.977995954] msec_range[4] 200.000000 - 500.000000 : 0 [20081216-15:38:42.980394063] msec_range[5] 100.000000 - 200.000000 : 0 [20081216-15:38:42.983039791] msec_range[6] 50.000000 - 100.000000 : 0 [20081216-15:38:42.985575814] msec_range[7] 20.000000 - 50.000000 : 0 [20081216-15:38:42.987836605] msec_range[8] 10.000000 - 20.000000 : 0 [20081216-15:38:42.990246594] msec_range[9] 5.000000 - 10.000000 : 0 [20081216-15:38:42.992595636] msec_range[10] 2.000000 - 5.000000 : 0 [20081216-15:38:42.994804267] msec_range[11] 1.000000 - 2.000000 : 0 [20081216-15:38:42.997313689] msec_range[12] 0.500000 - 1.000000 : 0 [20081216-15:38:42.999685044] msec_range[13] 0.200000 - 0.500000 : 0 [20081216-15:38:43.002024666] msec_range[14] 0.100000 - 0.200000 : 0 [20081216-15:38:43.004309059] msec_range[15] 0.050000 - 0.100000 : 0 [20081216-15:38:43.006443990] msec_range[16] 0.020000 - 0.050000 : 0 [20081216-15:38:43.008704026] msec_range[17] 0.010000 - 0.020000 : 16 [20081216-15:38:43.010999841] msec_range[18] 0.000000 - 0.010000 : 451 [20081216-15:38:43.013187917] [20081216-15:38:43.015440376] [20081216-15:38:43.017662361] [20081216-15:38:43.019794174] [20081216-15:38:43.022093692] 0.1% User Time [20081216-15:38:43.024265560] 1.2% System Time [20081216-15:38:43.026506291] 1.3% CPU Utilization [20081216-15:38:43.028669223] Profilers reporting [20081216-15:38:43.032813147] /autobench/scripts/doprofilers: line 33: 9040 Terminated ${CMDS[$i]} [20081216-15:38:43.035092365] /autobench/scripts/doprofilers: line 33: 9079 Terminated ${CMDS[$i]} [20081216-15:38:53.471607466] Profilers postprocessing [20081216-15:38:53.556475109] Processing File : iostat.001 [20081216-15:38:53.558664336] Discovered iostat_interval=[5] [20081216-15:38:54.086250693] Processing Directory : sar.breakout.001 [20081216-15:38:54.088551701] Discovered sar_interval=[5] [20081216-15:38:54.250429047] Processing File : mpstat.001 [20081216-15:38:54.252610218] Discovered mpstat_interval=[5] [20081216-15:38:55.384957506] Stopping profiling. [20081216-15:38:55.389787082] Killing daemon. [20081216-15:38:56.554062987] Processing File : /autobench/logs/ffsb.random_reads__threads_0008.08-12-16_15.33.31/analysis/oprofile.001 [20081216-15:38:56.556237195] Processing File : /autobench/logs/ffsb.random_reads__threads_0008.08-12-16_15.33.31/analysis/oprofile-brief.001 [20081216-15:38:57.564496445] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-16_1503/ext3-baseline' [20081216-15:38:59.022728355] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081216-15:38:59.350085463] PROCESSING COMMAND : 'mount -t ext3 /dev/ffsbdev1 /mnt/ffsb1' [20081216-15:38:59.448346513] PROCESSING COMMAND : 'run random_reads__threads_0032 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb num_threads=32' [20081216-15:38:59.500809674] new log requested [20081216-15:38:59.523475659] Running command ffsb [20081216-15:39:06.867694937] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb [20081216-15:39:06.880430349] Importing argument : num_threads=32 [20081216-15:39:06.906198465] Found a ext3 filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081216-15:39:06.971149639] FFSB version 6.0-RC2 started [20081216-15:39:06.973303461] [20081216-15:39:07.094174283] benchmark time = 300 [20081216-15:39:07.096093757] ThreadGroup 0 [20081216-15:39:07.097866182] ================ [20081216-15:39:07.099684600] num_threads = 32 [20081216-15:39:07.101647763] [20081216-15:39:07.103825649] read_random = on [20081216-15:39:07.105709377] read_size = 1048576 (1MB) [20081216-15:39:07.107523213] read_blocksize = 4096 (4KB) [20081216-15:39:07.109270893] read_skip = off [20081216-15:39:07.111135814] read_skipsize = 0 (0B) [20081216-15:39:07.112918418] [20081216-15:39:07.114699876] write_random = off [20081216-15:39:07.116491283] write_size = 0 (0B) [20081216-15:39:07.118346276] fsync_file = 0 [20081216-15:39:07.120103759] write_blocksize = 0 (0B) [20081216-15:39:07.121906710] wait time = 0 [20081216-15:39:07.123626571] [20081216-15:39:07.125452756] op weights [20081216-15:39:07.127222965] read = 1 (100.00%) [20081216-15:39:07.129016768] readall = 0 (0.00%) [20081216-15:39:07.130739512] write = 0 (0.00%) [20081216-15:39:07.132571599] create = 0 (0.00%) [20081216-15:39:07.134323214] append = 0 (0.00%) [20081216-15:39:07.136208252] delete = 0 (0.00%) [20081216-15:39:07.137957152] metaop = 0 (0.00%) [20081216-15:39:07.139791396] createdir = 0 (0.00%) [20081216-15:39:07.141553052] stat = 0 (0.00%) [20081216-15:39:07.143401585] writeall = 0 (0.00%) [20081216-15:39:07.145169785] writeall_fsync = 0 (0.00%) [20081216-15:39:07.147009169] open_close = 0 (0.00%) [20081216-15:39:07.148810784] write_fsync = 0 (0.00%) [20081216-15:39:07.150876277] create_fsync = 0 (0.00%) [20081216-15:39:07.152887448] append_fsync = 0 (0.00%) [20081216-15:39:07.154665669] [20081216-15:39:07.156474399] FileSystem /mnt/ffsb1 [20081216-15:39:07.158260998] ========== [20081216-15:39:07.160130719] num_dirs = 0 [20081216-15:39:07.161895105] starting files = 1024 [20081216-15:39:07.163738257] [20081216-15:39:07.165498790] min file size = 36700160 (35MB) [20081216-15:39:07.167351465] max file size = 36700160 (35MB) [20081216-15:39:07.169111415] directio = off [20081216-15:39:07.170902349] alignedio = on [20081216-15:39:07.172649546] bufferedio = off [20081216-15:39:07.174468742] [20081216-15:39:07.176254051] aging is off [20081216-15:39:07.178044295] current utilization = 52.33% [20081216-15:39:07.179788756] [20081216-15:39:07.181617858] checking existing fs: /mnt/ffsb1 [20081216-15:39:07.237420682] fs setup took 0 secs [20081216-15:39:08.167351630] Syncing()...0 sec [20081216-15:39:08.169415310] Starting Actual Benchmark At: Tue Dec 16 15:39:08 2008 [20081216-15:39:08.182363070] [20081216-15:44:17.897853878] Syncing()...0 sec [20081216-15:44:17.900714233] FFSB benchmark finished at: Tue Dec 16 15:44:17 2008 [20081216-15:44:17.904003316] [20081216-15:44:17.906706467] Results: [20081216-15:44:17.922192711] Benchmark took 309.73 sec [20081216-15:44:17.924622411] [20081216-15:44:17.926918729] Total Results [20081216-15:44:17.942093892] =============== [20081216-15:44:17.944698515] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081216-15:44:17.947520656] ======= ============ ========= ======= =========== ========== [20081216-15:44:17.950343714] read : 153088 494.26 100.000% 100.000% 1.93MB/sec [20081216-15:44:17.952902756] - [20081216-15:44:17.955259204] 494.26 Transactions per Second [20081216-15:44:17.957816802] [20081216-15:44:17.960896585] Throughput Results [20081216-15:44:17.978510191] =================== [20081216-15:44:17.981361442] Read Throughput: 1.93MB/sec [20081216-15:44:17.984086364] [20081216-15:44:17.988430817] System Call Latency statistics in millisecs [20081216-15:44:17.991048163] ===== [20081216-15:44:17.993828536] Min Avg Max Total Calls [20081216-15:44:17.996629370] ======== ======== ======== ============ [20081216-15:44:17.999438042] [ open] 0.006000 0.017773 1.106000 598 [20081216-15:44:18.002117862] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081216-15:44:18.004703693] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081216-15:44:18.007640528] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081216-15:44:18.010423799] msec_range[3] 500.000000 - 1000.000000 : 0 [20081216-15:44:18.012908327] msec_range[4] 200.000000 - 500.000000 : 0 [20081216-15:44:18.016216456] msec_range[5] 100.000000 - 200.000000 : 0 [20081216-15:44:18.019057244] msec_range[6] 50.000000 - 100.000000 : 0 [20081216-15:44:18.021967460] msec_range[7] 20.000000 - 50.000000 : 0 [20081216-15:44:18.024876319] msec_range[8] 10.000000 - 20.000000 : 0 [20081216-15:44:18.027685507] msec_range[9] 5.000000 - 10.000000 : 0 [20081216-15:44:18.034236619] msec_range[10] 2.000000 - 5.000000 : 0 [20081216-15:44:18.037020921] msec_range[11] 1.000000 - 2.000000 : 1 [20081216-15:44:18.039849462] msec_range[12] 0.500000 - 1.000000 : 0 [20081216-15:44:18.042481685] msec_range[13] 0.200000 - 0.500000 : 0 [20081216-15:44:18.045238205] msec_range[14] 0.100000 - 0.200000 : 0 [20081216-15:44:18.047847842] msec_range[15] 0.050000 - 0.100000 : 0 [20081216-15:44:18.051339730] msec_range[16] 0.020000 - 0.050000 : 152 [20081216-15:44:18.053830242] msec_range[17] 0.010000 - 0.020000 : 349 [20081216-15:44:18.056091195] msec_range[18] 0.000000 - 0.010000 : 96 [20081216-15:44:18.058518077] [20081216-15:44:18.061020927] [ read] 0.002000 63.877467 3535.290039 153088 [20081216-15:44:18.063660657] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081216-15:44:18.066136307] msec_range[1] 2000.000000 - 5000.000000 : 40 [20081216-15:44:18.070047090] msec_range[2] 1000.000000 - 2000.000000 : 571 [20081216-15:44:18.073222744] msec_range[3] 500.000000 - 1000.000000 : 2542 [20081216-15:44:18.076128308] msec_range[4] 200.000000 - 500.000000 : 9231 [20081216-15:44:18.079299659] msec_range[5] 100.000000 - 200.000000 : 11994 [20081216-15:44:18.082128844] msec_range[6] 50.000000 - 100.000000 : 16789 [20081216-15:44:18.084627197] msec_range[7] 20.000000 - 50.000000 : 29046 [20081216-15:44:18.087216115] msec_range[8] 10.000000 - 20.000000 : 23652 [20081216-15:44:18.089521684] msec_range[9] 5.000000 - 10.000000 : 22615 [20081216-15:44:18.092521766] msec_range[10] 2.000000 - 5.000000 : 25773 [20081216-15:44:18.095449215] msec_range[11] 1.000000 - 2.000000 : 7484 [20081216-15:44:18.097918567] msec_range[12] 0.500000 - 1.000000 : 118 [20081216-15:44:18.100418267] msec_range[13] 0.200000 - 0.500000 : 52 [20081216-15:44:18.103266580] msec_range[14] 0.100000 - 0.200000 : 0 [20081216-15:44:18.106198526] msec_range[15] 0.050000 - 0.100000 : 0 [20081216-15:44:18.110375532] msec_range[16] 0.020000 - 0.050000 : 2 [20081216-15:44:18.114061958] msec_range[17] 0.010000 - 0.020000 : 574 [20081216-15:44:18.118061961] msec_range[18] 0.000000 - 0.010000 : 2605 [20081216-15:44:18.121850852] [20081216-15:44:18.125250457] [ lseek] 0.000000 0.001209 0.022000 153088 [20081216-15:44:18.127998785] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081216-15:44:18.131359591] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081216-15:44:18.134343965] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081216-15:44:18.136665879] msec_range[3] 500.000000 - 1000.000000 : 0 [20081216-15:44:18.139281907] msec_range[4] 200.000000 - 500.000000 : 0 [20081216-15:44:18.141887818] msec_range[5] 100.000000 - 200.000000 : 0 [20081216-15:44:18.144832430] msec_range[6] 50.000000 - 100.000000 : 0 [20081216-15:44:18.147522367] msec_range[7] 20.000000 - 50.000000 : 0 [20081216-15:44:18.150328860] msec_range[8] 10.000000 - 20.000000 : 0 [20081216-15:44:18.152945775] msec_range[9] 5.000000 - 10.000000 : 0 [20081216-15:44:18.155285225] msec_range[10] 2.000000 - 5.000000 : 0 [20081216-15:44:18.158075531] msec_range[11] 1.000000 - 2.000000 : 0 [20081216-15:44:18.160628319] msec_range[12] 0.500000 - 1.000000 : 0 [20081216-15:44:18.163180831] msec_range[13] 0.200000 - 0.500000 : 0 [20081216-15:44:18.165809938] msec_range[14] 0.100000 - 0.200000 : 0 [20081216-15:44:18.168361988] msec_range[15] 0.050000 - 0.100000 : 0 [20081216-15:44:18.171214375] msec_range[16] 0.020000 - 0.050000 : 2 [20081216-15:44:18.175466017] msec_range[17] 0.010000 - 0.020000 : 66 [20081216-15:44:18.178339564] msec_range[18] 0.000000 - 0.010000 : 153020 [20081216-15:44:18.180988659] [20081216-15:44:18.183559889] [ close] 0.002000 0.004651 0.015000 598 [20081216-15:44:18.186326666] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081216-15:44:18.188643523] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081216-15:44:18.191016376] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081216-15:44:18.195339966] msec_range[3] 500.000000 - 1000.000000 : 0 [20081216-15:44:18.198134013] msec_range[4] 200.000000 - 500.000000 : 0 [20081216-15:44:18.200762319] msec_range[5] 100.000000 - 200.000000 : 0 [20081216-15:44:18.203705503] msec_range[6] 50.000000 - 100.000000 : 0 [20081216-15:44:18.206035628] msec_range[7] 20.000000 - 50.000000 : 0 [20081216-15:44:18.208484513] msec_range[8] 10.000000 - 20.000000 : 0 [20081216-15:44:18.210755990] msec_range[9] 5.000000 - 10.000000 : 0 [20081216-15:44:18.213137821] msec_range[10] 2.000000 - 5.000000 : 0 [20081216-15:44:18.215877878] msec_range[11] 1.000000 - 2.000000 : 0 [20081216-15:44:18.218961970] msec_range[12] 0.500000 - 1.000000 : 0 [20081216-15:44:18.221210015] msec_range[13] 0.200000 - 0.500000 : 0 [20081216-15:44:18.223545649] msec_range[14] 0.100000 - 0.200000 : 0 [20081216-15:44:18.225619654] msec_range[15] 0.050000 - 0.100000 : 0 [20081216-15:44:18.227870821] msec_range[16] 0.020000 - 0.050000 : 0 [20081216-15:44:18.230171600] msec_range[17] 0.010000 - 0.020000 : 21 [20081216-15:44:18.232305352] msec_range[18] 0.000000 - 0.010000 : 577 [20081216-15:44:18.234592189] [20081216-15:44:18.236964804] [20081216-15:44:18.239127849] [20081216-15:44:18.241351760] [20081216-15:44:18.243680668] 0.1% User Time [20081216-15:44:18.245799126] 1.6% System Time [20081216-15:44:18.248006401] 1.7% CPU Utilization [20081216-15:44:18.250249349] Profilers reporting [20081216-15:44:18.252343299] /autobench/scripts/doprofilers: line 33: 14950 Terminated ${CMDS[$i]} [20081216-15:44:18.254541946] /autobench/scripts/doprofilers: line 33: 14989 Terminated ${CMDS[$i]} [20081216-15:44:30.489992973] Profilers postprocessing [20081216-15:44:30.576765208] Processing File : iostat.001 [20081216-15:44:30.579297045] Discovered iostat_interval=[5] [20081216-15:44:31.111468388] Processing Directory : sar.breakout.001 [20081216-15:44:31.113622785] Discovered sar_interval=[5] [20081216-15:44:31.274952588] Processing File : mpstat.001 [20081216-15:44:31.278631818] Discovered mpstat_interval=[5] [20081216-15:44:32.410948633] Stopping profiling. [20081216-15:44:32.416492112] Killing daemon. [20081216-15:44:33.580509294] Processing File : /autobench/logs/ffsb.random_reads__threads_0032.08-12-16_15.38.59/analysis/oprofile.001 [20081216-15:44:33.582669429] Processing File : /autobench/logs/ffsb.random_reads__threads_0032.08-12-16_15.38.59/analysis/oprofile-brief.001 [20081216-15:44:34.743348828] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-16_1503/ext3-baseline' [20081216-15:44:36.116823276] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081216-15:44:36.566429516] PROCESSING COMMAND : 'mount -t ext3 /dev/ffsbdev1 /mnt/ffsb1' [20081216-15:44:36.697633927] PROCESSING COMMAND : 'run random_writes__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb num_threads=1' [20081216-15:44:36.743690959] new log requested [20081216-15:44:36.766375952] Running command ffsb [20081216-15:44:44.095179709] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb [20081216-15:44:44.119587143] Importing argument : num_threads=1 [20081216-15:44:44.145692627] Found a ext3 filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081216-15:44:44.210600727] FFSB version 6.0-RC2 started [20081216-15:44:44.212918818] [20081216-15:44:44.214738420] benchmark time = 300 [20081216-15:44:44.216571764] ThreadGroup 0 [20081216-15:44:44.218449754] ================ [20081216-15:44:44.220187038] num_threads = 1 [20081216-15:44:44.222139926] [20081216-15:44:44.224030407] read_random = off [20081216-15:44:44.225881526] read_size = 0 (0B) [20081216-15:44:44.227610799] read_blocksize = 0 (0B) [20081216-15:44:44.229444342] read_skip = off [20081216-15:44:44.231216061] read_skipsize = 0 (0B) [20081216-15:44:44.233015594] [20081216-15:44:44.234741320] write_random = on [20081216-15:44:44.236523150] write_size = 1048576 (1MB) [20081216-15:44:44.238325174] fsync_file = 0 [20081216-15:44:44.240136186] write_blocksize = 4096 (4KB) [20081216-15:44:44.241851237] wait time = 0 [20081216-15:44:44.243695281] [20081216-15:44:44.245699620] op weights [20081216-15:44:44.247834379] read = 0 (0.00%) [20081216-15:44:44.249702863] readall = 0 (0.00%) [20081216-15:44:44.251532868] write = 1 (100.00%) [20081216-15:44:44.253311229] create = 0 (0.00%) [20081216-15:44:44.255171860] append = 0 (0.00%) [20081216-15:44:44.257037098] delete = 0 (0.00%) [20081216-15:44:44.258779296] metaop = 0 (0.00%) [20081216-15:44:44.260633664] createdir = 0 (0.00%) [20081216-15:44:44.262449210] stat = 0 (0.00%) [20081216-15:44:44.264310563] writeall = 0 (0.00%) [20081216-15:44:44.266079994] writeall_fsync = 0 (0.00%) [20081216-15:44:44.267906731] open_close = 0 (0.00%) [20081216-15:44:44.269674667] write_fsync = 0 (0.00%) [20081216-15:44:44.271492594] create_fsync = 0 (0.00%) [20081216-15:44:44.273241551] append_fsync = 0 (0.00%) [20081216-15:44:44.275091052] [20081216-15:44:44.276952899] FileSystem /mnt/ffsb1 [20081216-15:44:44.278861965] ========== [20081216-15:44:44.280673551] num_dirs = 0 [20081216-15:44:44.282518706] starting files = 1024 [20081216-15:44:44.284287031] [20081216-15:44:44.286125032] min file size = 36700160 (35MB) [20081216-15:44:44.287928774] max file size = 36700160 (35MB) [20081216-15:44:44.289787906] directio = off [20081216-15:44:44.291677883] alignedio = on [20081216-15:44:44.293460597] bufferedio = off [20081216-15:44:44.295270958] [20081216-15:44:44.297046969] aging is off [20081216-15:44:44.298904122] current utilization = 52.33% [20081216-15:44:44.300722873] [20081216-15:44:44.302476932] checking existing fs: /mnt/ffsb1 [20081216-15:44:44.343182749] fs setup took 0 secs [20081216-15:44:45.215101767] Syncing()...0 sec [20081216-15:44:45.216946905] Starting Actual Benchmark At: Tue Dec 16 15:44:45 2008 [20081216-15:44:45.229700587] [20081216-15:49:50.053535748] Syncing()...2 sec [20081216-15:49:50.056621699] FFSB benchmark finished at: Tue Dec 16 15:49:50 2008 [20081216-15:49:50.059962495] [20081216-15:49:50.062546682] Results: [20081216-15:49:50.078011771] Benchmark took 304.84 sec [20081216-15:49:50.080240345] [20081216-15:49:50.082679352] Total Results [20081216-15:49:50.098145460] =============== [20081216-15:49:50.100748944] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081216-15:49:50.103335469] ======= ============ ========= ======= =========== ========== [20081216-15:49:50.106204913] write : 180992 593.73 100.000% 100.000% 81.2MB/sec [20081216-15:49:50.108507981] - [20081216-15:49:50.111099337] 593.73 Transactions per Second [20081216-15:49:50.113934683] [20081216-15:49:50.117444957] Throughput Results [20081216-15:49:50.133390032] =================== [20081216-15:49:50.136121271] Write Throughput: 81.2MB/sec [20081216-15:49:50.138522154] [20081216-15:49:50.140848422] System Call Latency statistics in millisecs [20081216-15:49:50.143720892] ===== [20081216-15:49:50.147624957] Min Avg Max Total Calls [20081216-15:49:50.150607136] ======== ======== ======== ============ [20081216-15:49:50.153821194] [ open] 0.006000 0.010325 0.043000 707 [20081216-15:49:50.157489063] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081216-15:49:50.159837421] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081216-15:49:50.162138301] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081216-15:49:50.164760079] msec_range[3] 500.000000 - 1000.000000 : 0 [20081216-15:49:50.168699205] msec_range[4] 200.000000 - 500.000000 : 0 [20081216-15:49:50.171415370] msec_range[5] 100.000000 - 200.000000 : 0 [20081216-15:49:50.173906705] msec_range[6] 50.000000 - 100.000000 : 0 [20081216-15:49:50.176416335] msec_range[7] 20.000000 - 50.000000 : 0 [20081216-15:49:50.179881230] msec_range[8] 10.000000 - 20.000000 : 0 [20081216-15:49:50.182597880] msec_range[9] 5.000000 - 10.000000 : 0 [20081216-15:49:50.185579231] msec_range[10] 2.000000 - 5.000000 : 0 [20081216-15:49:50.187958462] msec_range[11] 1.000000 - 2.000000 : 0 [20081216-15:49:50.190533733] msec_range[12] 0.500000 - 1.000000 : 0 [20081216-15:49:50.192757550] msec_range[13] 0.200000 - 0.500000 : 0 [20081216-15:49:50.195110989] msec_range[14] 0.100000 - 0.200000 : 0 [20081216-15:49:50.197435007] msec_range[15] 0.050000 - 0.100000 : 0 [20081216-15:49:50.199621389] msec_range[16] 0.020000 - 0.050000 : 46 [20081216-15:49:50.202251562] msec_range[17] 0.010000 - 0.020000 : 212 [20081216-15:49:50.204907490] msec_range[18] 0.000000 - 0.010000 : 449 [20081216-15:49:50.209477944] [20081216-15:49:50.212794749] [ write] 0.005000 1.668924 2619.375000 180992 [20081216-15:49:50.216471256] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081216-15:49:50.219734410] msec_range[1] 2000.000000 - 5000.000000 : 24 [20081216-15:49:50.222332843] msec_range[2] 1000.000000 - 2000.000000 : 62 [20081216-15:49:50.224987794] msec_range[3] 500.000000 - 1000.000000 : 113 [20081216-15:49:50.227869816] msec_range[4] 200.000000 - 500.000000 : 173 [20081216-15:49:50.230621965] msec_range[5] 100.000000 - 200.000000 : 34 [20081216-15:49:50.233195560] msec_range[6] 50.000000 - 100.000000 : 11 [20081216-15:49:50.235544236] msec_range[7] 20.000000 - 50.000000 : 20 [20081216-15:49:50.237884990] msec_range[8] 10.000000 - 20.000000 : 84 [20081216-15:49:50.240665768] msec_range[9] 5.000000 - 10.000000 : 448 [20081216-15:49:50.243127345] msec_range[10] 2.000000 - 5.000000 : 2693 [20081216-15:49:50.246302043] msec_range[11] 1.000000 - 2.000000 : 965 [20081216-15:49:50.251121091] msec_range[12] 0.500000 - 1.000000 : 29 [20081216-15:49:50.254119079] msec_range[13] 0.200000 - 0.500000 : 13 [20081216-15:49:50.256880217] msec_range[14] 0.100000 - 0.200000 : 3 [20081216-15:49:50.260597696] msec_range[15] 0.050000 - 0.100000 : 405 [20081216-15:49:50.263116589] msec_range[16] 0.020000 - 0.050000 : 45047 [20081216-15:49:50.266169742] msec_range[17] 0.010000 - 0.020000 : 102021 [20081216-15:49:50.269179995] msec_range[18] 0.000000 - 0.010000 : 28847 [20081216-15:49:50.271804053] [20081216-15:49:50.275388786] [ lseek] 0.000000 0.001095 1.312000 180992 [20081216-15:49:50.278632368] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081216-15:49:50.282813631] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081216-15:49:50.285779160] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081216-15:49:50.289260015] msec_range[3] 500.000000 - 1000.000000 : 0 [20081216-15:49:50.292096554] msec_range[4] 200.000000 - 500.000000 : 0 [20081216-15:49:50.294690818] msec_range[5] 100.000000 - 200.000000 : 0 [20081216-15:49:50.298254410] msec_range[6] 50.000000 - 100.000000 : 0 [20081216-15:49:50.300977446] msec_range[7] 20.000000 - 50.000000 : 0 [20081216-15:49:50.304335154] msec_range[8] 10.000000 - 20.000000 : 0 [20081216-15:49:50.307193002] msec_range[9] 5.000000 - 10.000000 : 0 [20081216-15:49:50.309727754] msec_range[10] 2.000000 - 5.000000 : 0 [20081216-15:49:50.312332174] msec_range[11] 1.000000 - 2.000000 : 1 [20081216-15:49:50.314731659] msec_range[12] 0.500000 - 1.000000 : 0 [20081216-15:49:50.317422869] msec_range[13] 0.200000 - 0.500000 : 2 [20081216-15:49:50.320342436] msec_range[14] 0.100000 - 0.200000 : 0 [20081216-15:49:50.323255187] msec_range[15] 0.050000 - 0.100000 : 2 [20081216-15:49:50.325735759] msec_range[16] 0.020000 - 0.050000 : 8 [20081216-15:49:50.328108034] msec_range[17] 0.010000 - 0.020000 : 60 [20081216-15:49:50.330305621] msec_range[18] 0.000000 - 0.010000 : 180919 [20081216-15:49:50.332868918] [20081216-15:49:50.337097509] [ close] 0.002000 0.003123 0.011000 707 [20081216-15:49:50.339966949] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081216-15:49:50.342819897] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081216-15:49:50.345527194] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081216-15:49:50.348322095] msec_range[3] 500.000000 - 1000.000000 : 0 [20081216-15:49:50.351348743] msec_range[4] 200.000000 - 500.000000 : 0 [20081216-15:49:50.353785755] msec_range[5] 100.000000 - 200.000000 : 0 [20081216-15:49:50.355970543] msec_range[6] 50.000000 - 100.000000 : 0 [20081216-15:49:50.358516270] msec_range[7] 20.000000 - 50.000000 : 0 [20081216-15:49:50.361094899] msec_range[8] 10.000000 - 20.000000 : 0 [20081216-15:49:50.363509719] msec_range[9] 5.000000 - 10.000000 : 0 [20081216-15:49:50.365797317] msec_range[10] 2.000000 - 5.000000 : 0 [20081216-15:49:50.368227501] msec_range[11] 1.000000 - 2.000000 : 0 [20081216-15:49:50.370809685] msec_range[12] 0.500000 - 1.000000 : 0 [20081216-15:49:50.373216304] msec_range[13] 0.200000 - 0.500000 : 0 [20081216-15:49:50.375757966] msec_range[14] 0.100000 - 0.200000 : 0 [20081216-15:49:50.377895197] msec_range[15] 0.050000 - 0.100000 : 0 [20081216-15:49:50.380165495] msec_range[16] 0.020000 - 0.050000 : 0 [20081216-15:49:50.382450082] msec_range[17] 0.010000 - 0.020000 : 9 [20081216-15:49:50.384698812] msec_range[18] 0.000000 - 0.010000 : 698 [20081216-15:49:50.386785357] [20081216-15:49:50.389134928] [20081216-15:49:50.391699339] [20081216-15:49:50.394307474] [20081216-15:49:50.396994136] 0.1% User Time [20081216-15:49:50.399496679] 1.0% System Time [20081216-15:49:50.401943848] 1.1% CPU Utilization [20081216-15:49:50.404260434] Profilers reporting [20081216-15:49:50.406393505] /autobench/scripts/doprofilers: line 33: 20808 Terminated ${CMDS[$i]} [20081216-15:49:50.408702100] /autobench/scripts/doprofilers: line 33: 20846 Terminated ${CMDS[$i]} [20081216-15:50:02.282250602] Profilers postprocessing [20081216-15:50:02.367963970] Processing File : iostat.001 [20081216-15:50:02.370079435] Discovered iostat_interval=[5] [20081216-15:50:02.898063478] Processing Directory : sar.breakout.001 [20081216-15:50:02.900323215] Discovered sar_interval=[5] [20081216-15:50:03.060771718] Processing File : mpstat.001 [20081216-15:50:03.063072921] Discovered mpstat_interval=[5] [20081216-15:50:04.196954712] Stopping profiling. [20081216-15:50:04.201891056] Killing daemon. [20081216-15:50:05.367021005] Processing File : /autobench/logs/ffsb.random_writes__threads_0001.08-12-16_15.44.36/analysis/oprofile.001 [20081216-15:50:05.369239905] Processing File : /autobench/logs/ffsb.random_writes__threads_0001.08-12-16_15.44.36/analysis/oprofile-brief.001 [20081216-15:50:06.337765984] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-16_1503/ext3-baseline' [20081216-15:50:07.679980965] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081216-15:50:08.197043291] PROCESSING COMMAND : 'mount -t ext3 /dev/ffsbdev1 /mnt/ffsb1' [20081216-15:50:08.335707471] PROCESSING COMMAND : 'run random_writes__threads_0008 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb num_threads=8' [20081216-15:50:08.382725693] new log requested [20081216-15:50:08.416776242] Running command ffsb [20081216-15:50:15.721877626] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb [20081216-15:50:15.734199575] Importing argument : num_threads=8 [20081216-15:50:15.760155080] Found a ext3 filesystem on /dev/ffsbdev1 mounted on /mnt/ffsb1. [20081216-15:50:15.825430067] FFSB version 6.0-RC2 started [20081216-15:50:15.827641895] [20081216-15:50:15.856181544] benchmark time = 300 [20081216-15:50:15.857905662] ThreadGroup 0 [20081216-15:50:15.859714574] ================ [20081216-15:50:15.861655512] num_threads = 8 [20081216-15:50:15.863855332] [20081216-15:50:15.865998120] read_random = off [20081216-15:50:15.868009724] read_size = 0 (0B) [20081216-15:50:15.870151420] read_blocksize = 0 (0B) [20081216-15:50:15.872063524] read_skip = off [20081216-15:50:15.873919826] read_skipsize = 0 (0B) [20081216-15:50:15.875696496] [20081216-15:50:15.877541820] write_random = on [20081216-15:50:15.879280516] write_size = 1048576 (1MB) [20081216-15:50:15.881185088] fsync_file = 0 [20081216-15:50:15.883030860] write_blocksize = 4096 (4KB) [20081216-15:50:15.884881246] wait time = 0 [20081216-15:50:15.886670792] [20081216-15:50:15.888649768] op weights [20081216-15:50:15.890405880] read = 0 (0.00%) [20081216-15:50:15.892260991] readall = 0 (0.00%) [20081216-15:50:15.893982085] write = 1 (100.00%) [20081216-15:50:15.895813640] create = 0 (0.00%) [20081216-15:50:15.897544737] append = 0 (0.00%) [20081216-15:50:15.899353303] delete = 0 (0.00%) [20081216-15:50:15.901110941] metaop = 0 (0.00%) [20081216-15:50:15.902923093] createdir = 0 (0.00%) [20081216-15:50:15.904721066] stat = 0 (0.00%) [20081216-15:50:15.906546809] writeall = 0 (0.00%) [20081216-15:50:15.908408089] writeall_fsync = 0 (0.00%) [20081216-15:50:15.910203820] open_close = 0 (0.00%) [20081216-15:50:15.912055714] write_fsync = 0 (0.00%) [20081216-15:50:15.913834931] create_fsync = 0 (0.00%) [20081216-15:50:15.915644724] append_fsync = 0 (0.00%) [20081216-15:50:15.917403219] [20081216-15:50:15.919245301] FileSystem /mnt/ffsb1 [20081216-15:50:15.921075130] ========== [20081216-15:50:15.922822861] num_dirs = 0 [20081216-15:50:15.924667030] starting files = 1024 [20081216-15:50:15.926517524] [20081216-15:50:15.928280902] min file size = 36700160 (35MB) [20081216-15:50:15.930188864] max file size = 36700160 (35MB) [20081216-15:50:15.932034462] directio = off [20081216-15:50:15.933916845] alignedio = on [20081216-15:50:15.935781765] bufferedio = off [20081216-15:50:15.937567534] [20081216-15:50:15.939492885] aging is off [20081216-15:50:15.941278633] current utilization = 52.33% [20081216-15:50:15.943121431] [20081216-15:50:15.944984877] checking existing fs: /mnt/ffsb1 [20081216-15:50:16.000059310] fs setup took 0 secs [20081216-15:50:16.937515140] Syncing()...0 sec [20081216-15:50:16.939708614] Starting Actual Benchmark At: Tue Dec 16 15:50:16 2008 [20081216-15:50:16.953004964] [20081216-15:56:02.805816294] Syncing()...39 sec [20081216-15:56:02.808718915] FFSB benchmark finished at: Tue Dec 16 15:56:02 2008 [20081216-15:56:02.811686902] [20081216-15:56:02.814401006] Results: [20081216-15:56:02.830403733] Benchmark took 345.87 sec [20081216-15:56:02.833036763] [20081216-15:56:02.835634394] Total Results [20081216-15:56:02.851036223] =============== [20081216-15:56:02.853566779] Op Name Transactions Trans/sec % Trans % Op Weight Throughput [20081216-15:56:02.856181160] ======= ============ ========= ======= =========== ========== [20081216-15:56:02.858834003] write : 201984 583.99 100.000% 100.000% 79.8MB/sec [20081216-15:56:02.861580494] - [20081216-15:56:02.864165141] 583.99 Transactions per Second [20081216-15:56:02.866704875] [20081216-15:56:02.870287988] Throughput Results [20081216-15:56:02.886889405] =================== [20081216-15:56:02.889534817] Write Throughput: 79.8MB/sec [20081216-15:56:02.891924899] [20081216-15:56:02.894484650] System Call Latency statistics in millisecs [20081216-15:56:02.897149560] ===== [20081216-15:56:02.900108350] Min Avg Max Total Calls [20081216-15:56:02.906936170] ======== ======== ======== ============ [20081216-15:56:02.909442174] [ open] 0.006000 0.015594 0.180000 789 [20081216-15:56:02.912436588] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081216-15:56:02.915275987] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081216-15:56:02.917836692] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081216-15:56:02.920240819] msec_range[3] 500.000000 - 1000.000000 : 0 [20081216-15:56:02.922740321] msec_range[4] 200.000000 - 500.000000 : 0 [20081216-15:56:02.924984963] msec_range[5] 100.000000 - 200.000000 : 0 [20081216-15:56:02.927614944] msec_range[6] 50.000000 - 100.000000 : 0 [20081216-15:56:02.930412744] msec_range[7] 20.000000 - 50.000000 : 0 [20081216-15:56:02.933563435] msec_range[8] 10.000000 - 20.000000 : 0 [20081216-15:56:02.938520763] msec_range[9] 5.000000 - 10.000000 : 0 [20081216-15:56:02.941658439] msec_range[10] 2.000000 - 5.000000 : 0 [20081216-15:56:02.944484947] msec_range[11] 1.000000 - 2.000000 : 0 [20081216-15:56:02.947186090] msec_range[12] 0.500000 - 1.000000 : 0 [20081216-15:56:02.949945800] msec_range[13] 0.200000 - 0.500000 : 0 [20081216-15:56:02.952351623] msec_range[14] 0.100000 - 0.200000 : 3 [20081216-15:56:02.955623344] msec_range[15] 0.050000 - 0.100000 : 1 [20081216-15:56:02.959291424] msec_range[16] 0.020000 - 0.050000 : 206 [20081216-15:56:02.962357138] msec_range[17] 0.010000 - 0.020000 : 320 [20081216-15:56:02.964947858] msec_range[18] 0.000000 - 0.010000 : 259 [20081216-15:56:02.967654895] [20081216-15:56:02.970122372] [ write] 0.005000 11.894438 20465.962891 201984 [20081216-15:56:02.972648773] msec_range[0] 5000.000000 - 10000.000000 : 7 [20081216-15:56:02.975433136] msec_range[1] 2000.000000 - 5000.000000 : 42 [20081216-15:56:02.978123964] msec_range[2] 1000.000000 - 2000.000000 : 247 [20081216-15:56:02.980833680] msec_range[3] 500.000000 - 1000.000000 : 841 [20081216-15:56:02.983661445] msec_range[4] 200.000000 - 500.000000 : 2610 [20081216-15:56:02.986358092] msec_range[5] 100.000000 - 200.000000 : 313 [20081216-15:56:02.989134523] msec_range[6] 50.000000 - 100.000000 : 115 [20081216-15:56:02.991954404] msec_range[7] 20.000000 - 50.000000 : 190 [20081216-15:56:02.994792957] msec_range[8] 10.000000 - 20.000000 : 184 [20081216-15:56:02.997686289] msec_range[9] 5.000000 - 10.000000 : 179 [20081216-15:56:03.001845069] msec_range[10] 2.000000 - 5.000000 : 219 [20081216-15:56:03.004752018] msec_range[11] 1.000000 - 2.000000 : 104 [20081216-15:56:03.007289345] msec_range[12] 0.500000 - 1.000000 : 4 [20081216-15:56:03.010725272] msec_range[13] 0.200000 - 0.500000 : 10 [20081216-15:56:03.013453960] msec_range[14] 0.100000 - 0.200000 : 183 [20081216-15:56:03.016169042] msec_range[15] 0.050000 - 0.100000 : 2880 [20081216-15:56:03.018872485] msec_range[16] 0.020000 - 0.050000 : 56260 [20081216-15:56:03.021497159] msec_range[17] 0.010000 - 0.020000 : 103605 [20081216-15:56:03.024037592] msec_range[18] 0.000000 - 0.010000 : 33960 [20081216-15:56:03.026964870] [20081216-15:56:03.029566842] [ lseek] 0.000000 0.121518 15167.614258 201984 [20081216-15:56:03.031963486] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081216-15:56:03.034695333] msec_range[1] 2000.000000 - 5000.000000 : 1 [20081216-15:56:03.037560101] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081216-15:56:03.040999531] msec_range[3] 500.000000 - 1000.000000 : 2 [20081216-15:56:03.043768879] msec_range[4] 200.000000 - 500.000000 : 16 [20081216-15:56:03.050625691] msec_range[5] 100.000000 - 200.000000 : 3 [20081216-15:56:03.053640829] msec_range[6] 50.000000 - 100.000000 : 0 [20081216-15:56:03.056119194] msec_range[7] 20.000000 - 50.000000 : 1 [20081216-15:56:03.058342247] msec_range[8] 10.000000 - 20.000000 : 0 [20081216-15:56:03.060643252] msec_range[9] 5.000000 - 10.000000 : 1 [20081216-15:56:03.063513559] msec_range[10] 2.000000 - 5.000000 : 1 [20081216-15:56:03.065891361] msec_range[11] 1.000000 - 2.000000 : 0 [20081216-15:56:03.069238825] msec_range[12] 0.500000 - 1.000000 : 1 [20081216-15:56:03.071837453] msec_range[13] 0.200000 - 0.500000 : 1 [20081216-15:56:03.074378845] msec_range[14] 0.100000 - 0.200000 : 10 [20081216-15:56:03.077430477] msec_range[15] 0.050000 - 0.100000 : 87 [20081216-15:56:03.079648415] msec_range[16] 0.020000 - 0.050000 : 747 [20081216-15:56:03.082286172] msec_range[17] 0.010000 - 0.020000 : 716 [20081216-15:56:03.084875208] msec_range[18] 0.000000 - 0.010000 : 200396 [20081216-15:56:03.087262310] [20081216-15:56:03.089656133] [ close] 0.002000 0.004711 0.034000 789 [20081216-15:56:03.092048662] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081216-15:56:03.094531121] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081216-15:56:03.096805610] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081216-15:56:03.100129148] msec_range[3] 500.000000 - 1000.000000 : 0 [20081216-15:56:03.102415600] msec_range[4] 200.000000 - 500.000000 : 0 [20081216-15:56:03.107465710] msec_range[5] 100.000000 - 200.000000 : 0 [20081216-15:56:03.110283472] msec_range[6] 50.000000 - 100.000000 : 0 [20081216-15:56:03.112533038] msec_range[7] 20.000000 - 50.000000 : 0 [20081216-15:56:03.114825249] msec_range[8] 10.000000 - 20.000000 : 0 [20081216-15:56:03.117235382] msec_range[9] 5.000000 - 10.000000 : 0 [20081216-15:56:03.119437878] msec_range[10] 2.000000 - 5.000000 : 0 [20081216-15:56:03.121551227] msec_range[11] 1.000000 - 2.000000 : 0 [20081216-15:56:03.123801008] msec_range[12] 0.500000 - 1.000000 : 0 [20081216-15:56:03.126232846] msec_range[13] 0.200000 - 0.500000 : 0 [20081216-15:56:03.128860261] msec_range[14] 0.100000 - 0.200000 : 0 [20081216-15:56:03.131845202] msec_range[15] 0.050000 - 0.100000 : 0 [20081216-15:56:03.134126863] msec_range[16] 0.020000 - 0.050000 : 2 [20081216-15:56:03.136398364] msec_range[17] 0.010000 - 0.020000 : 50 [20081216-15:56:03.138634073] msec_range[18] 0.000000 - 0.010000 : 737 [20081216-15:56:03.140738720] [20081216-15:56:03.142999354] [20081216-15:56:03.145364757] [20081216-15:56:03.147744494] [20081216-15:56:03.149934835] 0.1% User Time [20081216-15:56:03.152364473] 1.2% System Time [20081216-15:56:03.154584732] 1.4% CPU Utilization [20081216-15:56:03.156599977] Profilers reporting [20081216-15:56:03.159010842] /autobench/scripts/doprofilers: line 33: 26666 Terminated ${CMDS[$i]} [20081216-15:56:03.161322648] /autobench/scripts/doprofilers: line 33: 26708 Terminated ${CMDS[$i]} [20081216-15:56:18.450545669] Profilers postprocessing [20081216-15:56:18.538096219] Processing File : iostat.001 [20081216-15:56:18.540232321] Discovered iostat_interval=[5] [20081216-15:56:19.104561042] Processing Directory : sar.breakout.001 [20081216-15:56:19.106838987] Discovered sar_interval=[5] [20081216-15:56:19.278356129] Processing File : mpstat.001 [20081216-15:56:19.280610051] Discovered mpstat_interval=[5] [20081216-15:56:20.413236410] Stopping profiling. [20081216-15:56:20.418144916] Killing daemon. [20081216-15:56:21.582881347] Processing File : /autobench/logs/ffsb.random_writes__threads_0008.08-12-16_15.50.08/analysis/oprofile.001 [20081216-15:56:21.585047431] Processing File : /autobench/logs/ffsb.random_writes__threads_0008.08-12-16_15.50.08/analysis/oprofile-brief.001 [20081216-15:56:22.993492165] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-12-16_1503/ext3-baseline'