[20081019-09:57:38.249025468] PROCESSING COMMAND : 'clearprofilers' [20081019-09:57:38.493688535] PROCESSING COMMAND : 'useprofiler iostat 5' [20081019-09:57:38.595919692] Checking for sar... [20081019-09:57:38.598071060] found [20081019-09:57:38.730315309] PROCESSING COMMAND : 'useprofiler sar 5' [20081019-09:57:38.833337001] Checking for sar... [20081019-09:57:38.835529979] found [20081019-09:57:38.968712158] PROCESSING COMMAND : 'useprofiler mpstat 5' [20081019-09:57:39.071797797] Checking for sar... [20081019-09:57:39.073953725] found [20081019-09:57:39.206460248] PROCESSING COMMAND : 'useprofiler oprofile' [20081019-09:57:39.356528740] Checking for gettext... [20081019-09:57:39.363459497] found [20081019-09:57:39.365514849] Checking for libiberty... [20081019-09:57:39.393690283] found [20081019-09:57:39.395714909] Checking for popt... [20081019-09:57:39.397879840] found [20081019-09:57:39.401803058] Checking for popt64... [20081019-09:57:39.403694928] found [20081019-09:57:39.405610498] Checking for oprofile... [20081019-09:57:39.409765622] found [20081019-09:57:39.474902760] opcontrol: oprofile 0.9.3 compiled on Sep 18 2008 16:10:26 [20081019-09:57:39.649330331] Daemon not running [20081019-09:57:40.253737609] Daemon not running [20081019-09:57:40.255643493] Separate options: none [20081019-09:57:40.257734200] vmlinux file: /boot/vmlinux-2.6.27-rc7 [20081019-09:57:40.259926454] Image filter: none [20081019-09:57:40.261718891] Call-graph depth: 0 [20081019-09:57:40.398261372] PROCESSING COMMAND : 'useprofiler blktrace DEVICES=/dev/ffsbdev1' [20081019-09:57:40.699550789] PROCESSING COMMAND : 'umount /mnt/ffsb1 > /dev/null 2>&1' [20081019-09:57:40.769817157] PROCESSING COMMAND : 'set-sched noop' [20081019-09:57:41.155256012] PROCESSING COMMAND : 'mkresultdirs hks.austin.ibm.com benchmarks/results/btrfs/ffsb btrfs2 2008-10-19_0957 ext3-baseline' [20081019-09:57:41.479784846] Connecting to hks.austin.ibm.com... [20081019-09:57:41.482050528] Remote working directory: /opt [20081019-09:57:41.484246136] Remote working directory: /opt/benchmarks/results/btrfs/ffsb [20081019-09:57:41.486189624] Couldn't create directory: Failure [20081019-09:57:41.488060435] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs2 [20081019-09:57:41.490120495] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs2 [20081019-09:57:41.492172929] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs2/2008-10-19_0957 [20081019-09:57:41.494120044] Remote working directory: /opt/benchmarks/results/btrfs/ffsb/btrfs2/2008-10-19_0957 [20081019-09:57:41.495894484] Changing mode on /opt/benchmarks/results/btrfs/ffsb/btrfs2/2008-10-19_0957/ext3-baseline [20081019-09:57:41.564767090] PROCESSING COMMAND : 'mkfs.ext3 -V > /autobench/logs//mkfs.version 2>&1' [20081019-09:57:41.708165941] PROCESSING COMMAND : 'mkfs.ext3 -F /dev/ffsbdev1' [20081019-09:57:41.728379694] mke2fs 1.41.2 (02-Oct-2008) [20081019-09:57:41.749638847] Filesystem label= [20081019-09:57:41.751708666] OS type: Linux [20081019-09:57:41.753727028] Block size=4096 (log=2) [20081019-09:57:41.755631544] Fragment size=4096 (log=2) [20081019-09:57:41.757425292] 4481024 inodes, 17921750 blocks [20081019-09:57:41.759083630] 896087 blocks (5.00%) reserved for the super user [20081019-09:57:41.760895862] First data block=0 [20081019-09:57:41.762678309] Maximum filesystem blocks=4294967296 [20081019-09:57:41.764326726] 547 block groups [20081019-09:57:41.766085281] 32768 blocks per group, 32768 fragments per group [20081019-09:57:41.767859118] 8192 inodes per group [20081019-09:57:41.769508557] Superblock backups stored on blocks: [20081019-09:57:41.771294088] 32768, 98304, 163840, 229376, 294912, 819200, 884736, 1605632, 2654208, [20081019-09:57:41.773068416] 4096000, 7962624, 11239424 [20081019-09:57:41.774716004] [20081019-09:57:53.541384327] 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 [20081019-09:57:55.385534186] Creating journal (32768 blocks): done [20081019-09:57:59.100321709] Writing superblocks and filesystem accounting information: done [20081019-09:57:59.529435474] [20081019-09:57:59.531446852] This filesystem will be automatically checked every 32 mounts or [20081019-09:57:59.533638515] 180 days, whichever comes first. Use tune2fs -c or -i to override. [20081019-09:57:59.687679877] PROCESSING COMMAND : 'mount -t ext3 /dev/ffsbdev1 /mnt/ffsb1' [20081019-09:57:59.827707319] PROCESSING COMMAND : 'run sequential_reads__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb num_threads=1' [20081019-09:57:59.879783268] new log requested [20081019-09:57:59.914485849] Running command ffsb [20081019-09:58:07.591752584] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb [20081019-09:58:07.604672342] Importing argument : num_threads=1 [20081019-09:58:07.702737143] Checking for sar... [20081019-09:58:07.705080816] found [20081019-09:58:07.760403750] Checking for sar... [20081019-09:58:07.762587526] found [20081019-09:58:07.817899039] Checking for sar... [20081019-09:58:07.819994740] found [20081019-09:58:07.893564414] Checking for gettext... [20081019-09:58:07.896647523] found [20081019-09:58:07.898674146] Checking for libiberty... [20081019-09:58:07.900629187] found [20081019-09:58:07.902674161] Checking for popt... [20081019-09:58:07.904449454] found [20081019-09:58:07.906149752] Checking for popt64... [20081019-09:58:07.907907453] found [20081019-09:58:07.909817393] Checking for oprofile... [20081019-09:58:07.911881322] found [20081019-09:58:07.958206385] opcontrol: oprofile 0.9.3 compiled on Sep 18 2008 16:10:26 [20081019-09:58:08.035858871] Daemon not running [20081019-09:58:08.045938281] Unloading oprofile module [20081019-09:58:08.149815854] Daemon not running [20081019-09:58:08.431101533] Daemon not running [20081019-09:58:08.433197359] Separate options: none [20081019-09:58:08.435266607] vmlinux file: /boot/vmlinux-2.6.27-rc7 [20081019-09:58:08.437262819] Image filter: none [20081019-09:58:08.439207189] Call-graph depth: 0 [20081019-09:58:08.565746973] FFSB version 5.2.1 started [20081019-09:58:08.567890140] [20081019-09:58:08.569844983] benchmark time = 300 [20081019-09:58:08.571864453] ThreadGroup 0 [20081019-09:58:08.573832534] ================ [20081019-09:58:08.575931333] num_threads = 1 [20081019-09:58:08.577875892] [20081019-09:58:08.579769987] read_random = off [20081019-09:58:08.581649218] read_size = 36700160 (35MB) [20081019-09:58:08.583372198] read_blocksize = 4096 (4KB) [20081019-09:58:08.585177710] read_skip = off [20081019-09:58:08.586978621] read_skipsize = 0 (0B) [20081019-09:58:08.588799300] [20081019-09:58:08.590502138] write_random = off [20081019-09:58:08.592297784] write_size = 0 (0B) [20081019-09:58:08.594026182] fsync_file = 0 [20081019-09:58:08.595797042] write_blocksize = 0 (0B) [20081019-09:58:08.597783554] wait time = 0 [20081019-09:58:08.599599734] [20081019-09:58:08.601440297] op weights [20081019-09:58:08.603183633] read = 1 (100.00%) [20081019-09:58:08.605001564] readall = 0 (0.00%) [20081019-09:58:08.606733034] write = 0 (0.00%) [20081019-09:58:08.608549164] create = 0 (0.00%) [20081019-09:58:08.610382285] append = 0 (0.00%) [20081019-09:58:08.612115500] delete = 0 (0.00%) [20081019-09:58:08.613938979] metaop = 0 (0.00%) [20081019-09:58:08.615668569] createdir = 0 (0.00%) [20081019-09:58:08.617450937] stat = 0 (0.00%) [20081019-09:58:08.619185237] writeall = 0 (0.00%) [20081019-09:58:08.621027513] writeall_fsync = 0 (0.00%) [20081019-09:58:08.622840340] open_close = 0 (0.00%) [20081019-09:58:08.624564669] [20081019-09:58:08.626389632] FileSystem /mnt/ffsb1 [20081019-09:58:08.628109159] ========== [20081019-09:58:08.629893722] num_dirs = 0 [20081019-09:58:08.631610330] starting files = 1024 [20081019-09:58:08.633431729] [20081019-09:58:08.635241440] min file size = 36700160 (35MB) [20081019-09:58:08.636964031] max file size = 36700160 (35MB) [20081019-09:58:08.638796257] directio = off [20081019-09:58:08.640511711] alignedio = on [20081019-09:58:08.642240780] bufferedio = off [20081019-09:58:08.643992378] [20081019-09:58:08.645795774] aging is off [20081019-09:58:08.647598471] current utilization = 0.26% [20081019-09:58:08.649332776] [20081019-09:58:08.651145215] checking existing fs: /mnt/ffsb1 [20081019-09:58:08.652866949] opendir: No such file or directory [20081019-09:58:08.654687197] recreating new fileset [20081019-10:06:08.107792864] fs setup took 479 secs [20081019-10:06:10.628725609] Syncing()...2 sec [20081019-10:06:10.631075328] Starting Actual Benchmark At: Sun Oct 19 10:06:10 2008 [20081019-10:06:10.691499358] [20081019-10:11:12.804494050] Syncing()...0 sec [20081019-10:11:12.840767437] FFSB benchmark finished at: Sun Oct 19 10:11:12 2008 [20081019-10:11:12.843272942] [20081019-10:11:12.845817267] Results: [20081019-10:11:12.874628933] Benchmark took 302.02 sec [20081019-10:11:12.876484233] [20081019-10:11:12.878786207] Total Results [20081019-10:11:12.892748054] =============== [20081019-10:11:12.895235131] Throughput: 22783.97 reads/sec -> 89MB/sec [20081019-10:11:12.897579868] 22783.97 Transactions per Second [20081019-10:11:12.900086014] [20081019-10:11:12.902171786] System Call Latency statistics in millisecs [20081019-10:11:12.904311309] ===== [20081019-10:11:12.906484445] Min Avg Max Total Calls [20081019-10:11:12.908653109] ======== ======== ======== ============ [20081019-10:11:12.910723821] [ open] 0.014000 0.143422 8.278000 768 [20081019-10:11:12.912889135] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:11:12.914771037] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081019-10:11:12.916842687] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081019-10:11:12.918752535] msec_range[3] 500.000000 - 1000.000000 : 0 [20081019-10:11:12.920814256] msec_range[4] 200.000000 - 500.000000 : 0 [20081019-10:11:12.922921213] msec_range[5] 100.000000 - 200.000000 : 0 [20081019-10:11:12.924920829] msec_range[6] 50.000000 - 100.000000 : 0 [20081019-10:11:12.927091845] msec_range[7] 20.000000 - 50.000000 : 0 [20081019-10:11:12.929074579] msec_range[8] 10.000000 - 20.000000 : 0 [20081019-10:11:12.931064339] msec_range[9] 5.000000 - 10.000000 : 9 [20081019-10:11:12.932988017] msec_range[10] 2.000000 - 5.000000 : 7 [20081019-10:11:12.934983347] msec_range[11] 1.000000 - 2.000000 : 0 [20081019-10:11:12.936883198] msec_range[12] 0.500000 - 1.000000 : 0 [20081019-10:11:12.938825594] msec_range[13] 0.200000 - 0.500000 : 6 [20081019-10:11:12.940695993] msec_range[14] 0.100000 - 0.200000 : 1 [20081019-10:11:12.942654971] msec_range[15] 0.050000 - 0.100000 : 28 [20081019-10:11:12.944528663] msec_range[16] 0.020000 - 0.050000 : 517 [20081019-10:11:12.946481099] msec_range[17] 0.010000 - 0.020000 : 200 [20081019-10:11:12.948362839] msec_range[18] 0.000000 - 0.010000 : 0 [20081019-10:11:12.950316063] [20081019-10:11:12.952190635] [ read] 0.004000 0.043451 44.661999 6881280 [20081019-10:11:12.954145983] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:11:12.956009375] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081019-10:11:12.957939339] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081019-10:11:12.959823503] msec_range[3] 500.000000 - 1000.000000 : 0 [20081019-10:11:12.961758325] msec_range[4] 200.000000 - 500.000000 : 0 [20081019-10:11:12.963638877] msec_range[5] 100.000000 - 200.000000 : 0 [20081019-10:11:12.965577682] msec_range[6] 50.000000 - 100.000000 : 0 [20081019-10:11:12.967447977] msec_range[7] 20.000000 - 50.000000 : 45 [20081019-10:11:12.969382371] msec_range[8] 10.000000 - 20.000000 : 5601 [20081019-10:11:12.971260486] msec_range[9] 5.000000 - 10.000000 : 12906 [20081019-10:11:12.973195945] msec_range[10] 2.000000 - 5.000000 : 28996 [20081019-10:11:12.975055197] msec_range[11] 1.000000 - 2.000000 : 703 [20081019-10:11:12.976961224] msec_range[12] 0.500000 - 1.000000 : 5697 [20081019-10:11:12.978819924] msec_range[13] 0.200000 - 0.500000 : 335 [20081019-10:11:12.980733194] msec_range[14] 0.100000 - 0.200000 : 744 [20081019-10:11:12.982651913] msec_range[15] 0.050000 - 0.100000 : 1097 [20081019-10:11:13.038131101] msec_range[16] 0.020000 - 0.050000 : 1177 [20081019-10:11:13.040195032] msec_range[17] 0.010000 - 0.020000 : 35809 [20081019-10:11:13.042184211] msec_range[18] 0.000000 - 0.010000 : 6788170 [20081019-10:11:13.044200409] [20081019-10:11:13.046269661] [ close] 0.003000 0.005987 0.014000 768 [20081019-10:11:13.048235529] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:11:13.050891362] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081019-10:11:13.052998113] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081019-10:11:13.055002865] msec_range[3] 500.000000 - 1000.000000 : 0 [20081019-10:11:13.057191719] msec_range[4] 200.000000 - 500.000000 : 0 [20081019-10:11:13.059255578] msec_range[5] 100.000000 - 200.000000 : 0 [20081019-10:11:13.062400915] msec_range[6] 50.000000 - 100.000000 : 0 [20081019-10:11:13.064578617] msec_range[7] 20.000000 - 50.000000 : 0 [20081019-10:11:13.066723787] msec_range[8] 10.000000 - 20.000000 : 0 [20081019-10:11:13.068757875] msec_range[9] 5.000000 - 10.000000 : 0 [20081019-10:11:13.070839160] msec_range[10] 2.000000 - 5.000000 : 0 [20081019-10:11:13.072922399] msec_range[11] 1.000000 - 2.000000 : 0 [20081019-10:11:13.074939925] msec_range[12] 0.500000 - 1.000000 : 0 [20081019-10:11:13.076988265] msec_range[13] 0.200000 - 0.500000 : 0 [20081019-10:11:13.079190800] msec_range[14] 0.100000 - 0.200000 : 0 [20081019-10:11:13.081275108] msec_range[15] 0.050000 - 0.100000 : 0 [20081019-10:11:13.083206981] msec_range[16] 0.020000 - 0.050000 : 0 [20081019-10:11:13.085485217] msec_range[17] 0.010000 - 0.020000 : 7 [20081019-10:11:13.088303442] msec_range[18] 0.000000 - 0.010000 : 761 [20081019-10:11:13.090235468] [20081019-10:11:13.092439889] [20081019-10:11:13.094574540] [20081019-10:11:13.096552666] [20081019-10:11:13.098418282] 1.5% User Time [20081019-10:11:13.100348286] 15.9% System Time [20081019-10:11:13.102227540] 17.3% CPU Utilization [20081019-10:11:13.202509922] Profilers reporting [20081019-10:11:16.296157239] Profilers postprocessing [20081019-10:11:17.506276777] Stopping profiling. [20081019-10:11:17.510871553] Killing daemon. [20081019-10:11:18.820425634] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0001.08-10-19_09.57.59/analysis/oprofile.001 [20081019-10:11:18.822718941] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0001.08-10-19_09.57.59/analysis/oprofile-brief.001 [20081019-10:11:19.005833954] Processing File : mpstat.001 [20081019-10:11:19.007719605] Discovered mpstat_interval=[5] [20081019-10:11:19.553426956] Processing Directory : sar.breakout.001 [20081019-10:11:19.555595745] Discovered sar_interval=[5] [20081019-10:11:19.683885244] Processing File : iostat.001 [20081019-10:11:19.686109254] Discovered iostat_interval=[5] [20081019-10:11:20.811918816] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-10-19_0957/ext3-baseline' [20081019-10:11:26.468796281] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081019-10:11:26.987150552] PROCESSING COMMAND : 'mount -t ext3 /dev/ffsbdev1 /mnt/ffsb1' [20081019-10:11:27.232540316] PROCESSING COMMAND : 'run sequential_reads__threads_0008 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb num_threads=8' [20081019-10:11:27.288989947] new log requested [20081019-10:11:27.335259441] Running command ffsb [20081019-10:11:35.168474676] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb [20081019-10:11:35.174191529] Importing argument : num_threads=8 [20081019-10:11:35.268750298] Checking for sar... [20081019-10:11:35.270900819] found [20081019-10:11:35.327165270] Checking for sar... [20081019-10:11:35.329283888] found [20081019-10:11:35.384706069] Checking for sar... [20081019-10:11:35.386750301] found [20081019-10:11:35.471849211] Checking for gettext... [20081019-10:11:35.492579936] found [20081019-10:11:35.494693431] Checking for libiberty... [20081019-10:11:35.516755079] found [20081019-10:11:35.518501135] Checking for popt... [20081019-10:11:35.523246416] found [20081019-10:11:35.531797636] Checking for popt64... [20081019-10:11:35.533829981] found [20081019-10:11:35.535915317] Checking for oprofile... [20081019-10:11:35.537928339] found [20081019-10:11:35.587838757] opcontrol: oprofile 0.9.3 compiled on Sep 18 2008 16:10:26 [20081019-10:11:35.664949137] Daemon not running [20081019-10:11:35.682813559] Unloading oprofile module [20081019-10:11:35.910780377] Daemon not running [20081019-10:11:36.323778669] Daemon not running [20081019-10:11:36.325913080] Separate options: none [20081019-10:11:36.327898591] vmlinux file: /boot/vmlinux-2.6.27-rc7 [20081019-10:11:36.330010503] Image filter: none [20081019-10:11:36.331975249] Call-graph depth: 0 [20081019-10:11:36.446639786] FFSB version 5.2.1 started [20081019-10:11:36.448619941] [20081019-10:11:36.475079959] benchmark time = 300 [20081019-10:11:36.477151079] ThreadGroup 0 [20081019-10:11:36.479147690] ================ [20081019-10:11:36.481194737] num_threads = 8 [20081019-10:11:36.483074925] [20081019-10:11:36.484804405] read_random = off [20081019-10:11:36.486535150] read_size = 36700160 (35MB) [20081019-10:11:36.488290318] read_blocksize = 4096 (4KB) [20081019-10:11:36.490158261] read_skip = off [20081019-10:11:36.491864597] read_skipsize = 0 (0B) [20081019-10:11:36.493899404] [20081019-10:11:36.495709210] write_random = off [20081019-10:11:36.497477032] write_size = 0 (0B) [20081019-10:11:36.499182787] fsync_file = 0 [20081019-10:11:36.500964161] write_blocksize = 0 (0B) [20081019-10:11:36.502687439] wait time = 0 [20081019-10:11:36.504425050] [20081019-10:11:36.506118634] op weights [20081019-10:11:36.507904356] read = 1 (100.00%) [20081019-10:11:36.509651255] readall = 0 (0.00%) [20081019-10:11:36.511329469] write = 0 (0.00%) [20081019-10:11:36.513036503] create = 0 (0.00%) [20081019-10:11:36.514971119] append = 0 (0.00%) [20081019-10:11:36.516809367] delete = 0 (0.00%) [20081019-10:11:36.518540655] metaop = 0 (0.00%) [20081019-10:11:36.520224061] createdir = 0 (0.00%) [20081019-10:11:36.522069427] stat = 0 (0.00%) [20081019-10:11:36.523929508] writeall = 0 (0.00%) [20081019-10:11:36.525645066] writeall_fsync = 0 (0.00%) [20081019-10:11:36.527466640] open_close = 0 (0.00%) [20081019-10:11:36.529222308] [20081019-10:11:36.530978245] FileSystem /mnt/ffsb1 [20081019-10:11:36.532641034] ========== [20081019-10:11:36.534411101] num_dirs = 0 [20081019-10:11:36.536079163] starting files = 1024 [20081019-10:11:36.537880608] [20081019-10:11:36.539553793] min file size = 36700160 (35MB) [20081019-10:11:36.541624926] max file size = 36700160 (35MB) [20081019-10:11:36.543570442] directio = off [20081019-10:11:36.545288762] alignedio = on [20081019-10:11:36.547021575] bufferedio = off [20081019-10:11:36.548868205] [20081019-10:11:36.550574286] aging is off [20081019-10:11:36.552269432] current utilization = 52.33% [20081019-10:11:36.553991234] [20081019-10:11:36.555762361] checking existing fs: /mnt/ffsb1 [20081019-10:11:36.605711457] fs setup took 0 secs [20081019-10:11:36.944215525] Syncing()...0 sec [20081019-10:11:36.945958847] Starting Actual Benchmark At: Sun Oct 19 10:11:36 2008 [20081019-10:11:36.959146227] [20081019-10:16:40.789718779] Syncing()...0 sec [20081019-10:16:40.819897329] FFSB benchmark finished at: Sun Oct 19 10:16:40 2008 [20081019-10:16:40.822399556] [20081019-10:16:40.824962527] Results: [20081019-10:16:40.889336679] Benchmark took 303.71 sec [20081019-10:16:40.891398125] [20081019-10:16:40.893248227] Total Results [20081019-10:16:40.917644807] =============== [20081019-10:16:40.919523531] Throughput: 19530.22 reads/sec -> 76.3MB/sec [20081019-10:16:40.927771883] 19530.22 Transactions per Second [20081019-10:16:40.929965906] [20081019-10:16:40.931801093] System Call Latency statistics in millisecs [20081019-10:16:40.934153204] ===== [20081019-10:16:40.936152319] Min Avg Max Total Calls [20081019-10:16:40.938104256] ======== ======== ======== ============ [20081019-10:16:40.940015076] [ open] 0.006000 5.105790 465.514008 662 [20081019-10:16:40.942213044] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:16:40.944609694] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081019-10:16:40.946782979] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081019-10:16:40.949303032] msec_range[3] 500.000000 - 1000.000000 : 0 [20081019-10:16:40.951411860] msec_range[4] 200.000000 - 500.000000 : 5 [20081019-10:16:40.953396706] msec_range[5] 100.000000 - 200.000000 : 7 [20081019-10:16:40.955280635] msec_range[6] 50.000000 - 100.000000 : 8 [20081019-10:16:40.957307145] msec_range[7] 20.000000 - 50.000000 : 1 [20081019-10:16:40.959242022] msec_range[8] 10.000000 - 20.000000 : 2 [20081019-10:16:40.961231448] msec_range[9] 5.000000 - 10.000000 : 0 [20081019-10:16:40.963148273] msec_range[10] 2.000000 - 5.000000 : 1 [20081019-10:16:40.965149952] msec_range[11] 1.000000 - 2.000000 : 1 [20081019-10:16:40.967022716] msec_range[12] 0.500000 - 1.000000 : 4 [20081019-10:16:40.968973329] msec_range[13] 0.200000 - 0.500000 : 11 [20081019-10:16:40.970848139] msec_range[14] 0.100000 - 0.200000 : 0 [20081019-10:16:40.972903011] msec_range[15] 0.050000 - 0.100000 : 55 [20081019-10:16:40.974984297] msec_range[16] 0.020000 - 0.050000 : 440 [20081019-10:16:40.976999700] msec_range[17] 0.010000 - 0.020000 : 124 [20081019-10:16:40.979207900] msec_range[18] 0.000000 - 0.010000 : 3 [20081019-10:16:40.981221654] [20081019-10:16:40.983188716] [ read] 0.001000 0.407376 3758.757080 5931520 [20081019-10:16:40.985251674] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:16:40.987417037] msec_range[1] 2000.000000 - 5000.000000 : 219 [20081019-10:16:40.989591888] msec_range[2] 1000.000000 - 2000.000000 : 409 [20081019-10:16:40.992349988] msec_range[3] 500.000000 - 1000.000000 : 476 [20081019-10:16:40.994633254] msec_range[4] 200.000000 - 500.000000 : 1181 [20081019-10:16:40.996578884] msec_range[5] 100.000000 - 200.000000 : 1476 [20081019-10:16:40.998595588] msec_range[6] 50.000000 - 100.000000 : 2550 [20081019-10:16:41.000612604] msec_range[7] 20.000000 - 50.000000 : 813 [20081019-10:16:41.002827147] msec_range[8] 10.000000 - 20.000000 : 4567 [20081019-10:16:41.004949282] msec_range[9] 5.000000 - 10.000000 : 9978 [20081019-10:16:41.007610340] msec_range[10] 2.000000 - 5.000000 : 19480 [20081019-10:16:41.011226520] msec_range[11] 1.000000 - 2.000000 : 434 [20081019-10:16:41.013432230] msec_range[12] 0.500000 - 1.000000 : 2787 [20081019-10:16:41.015484610] msec_range[13] 0.200000 - 0.500000 : 2596 [20081019-10:16:41.017640944] msec_range[14] 0.100000 - 0.200000 : 422 [20081019-10:16:41.019704389] msec_range[15] 0.050000 - 0.100000 : 959 [20081019-10:16:41.021643035] msec_range[16] 0.020000 - 0.050000 : 1108 [20081019-10:16:41.023768778] msec_range[17] 0.010000 - 0.020000 : 38901 [20081019-10:16:41.025932886] msec_range[18] 0.000000 - 0.010000 : 5843164 [20081019-10:16:41.028109976] [20081019-10:16:41.030286863] [ close] 0.003000 0.005965 0.014000 662 [20081019-10:16:41.032344515] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:16:41.034446442] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081019-10:16:41.036363541] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081019-10:16:41.038316586] msec_range[3] 500.000000 - 1000.000000 : 0 [20081019-10:16:41.040497234] msec_range[4] 200.000000 - 500.000000 : 0 [20081019-10:16:41.042450006] msec_range[5] 100.000000 - 200.000000 : 0 [20081019-10:16:41.044395738] msec_range[6] 50.000000 - 100.000000 : 0 [20081019-10:16:41.046325360] msec_range[7] 20.000000 - 50.000000 : 0 [20081019-10:16:41.048409305] msec_range[8] 10.000000 - 20.000000 : 0 [20081019-10:16:41.050420831] msec_range[9] 5.000000 - 10.000000 : 0 [20081019-10:16:41.052396442] msec_range[10] 2.000000 - 5.000000 : 0 [20081019-10:16:41.054301452] msec_range[11] 1.000000 - 2.000000 : 0 [20081019-10:16:41.056491290] msec_range[12] 0.500000 - 1.000000 : 0 [20081019-10:16:41.058417733] msec_range[13] 0.200000 - 0.500000 : 0 [20081019-10:16:41.060474495] msec_range[14] 0.100000 - 0.200000 : 0 [20081019-10:16:41.062412843] msec_range[15] 0.050000 - 0.100000 : 0 [20081019-10:16:41.064394162] msec_range[16] 0.020000 - 0.050000 : 0 [20081019-10:16:41.066298237] msec_range[17] 0.010000 - 0.020000 : 8 [20081019-10:16:41.068284672] msec_range[18] 0.000000 - 0.010000 : 654 [20081019-10:16:41.070192371] [20081019-10:16:41.072172835] [20081019-10:16:41.074123707] [20081019-10:16:41.076052378] [20081019-10:16:41.077926583] 1.2% User Time [20081019-10:16:41.079951445] 12.7% System Time [20081019-10:16:41.081851409] 13.9% CPU Utilization [20081019-10:16:41.083810103] Profilers reporting [20081019-10:16:44.192596454] Profilers postprocessing [20081019-10:16:45.437863964] Stopping profiling. [20081019-10:16:45.441909955] Killing daemon. [20081019-10:16:45.854827951] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0008.08-10-19_10.11.27/analysis/oprofile.001 [20081019-10:16:45.856948844] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0008.08-10-19_10.11.27/analysis/oprofile-brief.001 [20081019-10:16:46.053859998] Processing File : mpstat.001 [20081019-10:16:46.055882660] Discovered mpstat_interval=[5] [20081019-10:16:46.613628241] Processing Directory : sar.breakout.001 [20081019-10:16:46.615818367] Discovered sar_interval=[5] [20081019-10:16:46.750837456] Processing File : iostat.001 [20081019-10:16:46.752898146] Discovered iostat_interval=[5] [20081019-10:16:47.858230326] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-10-19_0957/ext3-baseline' [20081019-10:16:53.736011560] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081019-10:16:54.233074447] PROCESSING COMMAND : 'mount -t ext3 /dev/ffsbdev1 /mnt/ffsb1' [20081019-10:16:54.496561654] PROCESSING COMMAND : 'run sequential_reads__threads_0032 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb num_threads=32' [20081019-10:16:54.553701959] new log requested [20081019-10:16:54.582426361] Running command ffsb [20081019-10:17:02.495787058] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/sequential_reads.ffsb [20081019-10:17:02.501320250] Importing argument : num_threads=32 [20081019-10:17:02.596253937] Checking for sar... [20081019-10:17:02.598460134] found [20081019-10:17:02.654426446] Checking for sar... [20081019-10:17:02.656514995] found [20081019-10:17:02.711870634] Checking for sar... [20081019-10:17:02.713815533] found [20081019-10:17:02.799445168] Checking for gettext... [20081019-10:17:02.819909590] found [20081019-10:17:02.821860702] Checking for libiberty... [20081019-10:17:02.844036161] found [20081019-10:17:02.845784997] Checking for popt... [20081019-10:17:02.850600713] found [20081019-10:17:02.858594501] Checking for popt64... [20081019-10:17:02.860750771] found [20081019-10:17:02.862752836] Checking for oprofile... [20081019-10:17:02.864492350] found [20081019-10:17:02.914044482] opcontrol: oprofile 0.9.3 compiled on Sep 18 2008 16:10:26 [20081019-10:17:02.992757686] Daemon not running [20081019-10:17:03.013247037] Unloading oprofile module [20081019-10:17:03.228557476] Daemon not running [20081019-10:17:03.645978946] Daemon not running [20081019-10:17:03.648096563] Separate options: none [20081019-10:17:03.650238241] vmlinux file: /boot/vmlinux-2.6.27-rc7 [20081019-10:17:03.652387344] Image filter: none [20081019-10:17:03.654328678] Call-graph depth: 0 [20081019-10:17:03.769429740] FFSB version 5.2.1 started [20081019-10:17:03.771202570] [20081019-10:17:03.888969666] benchmark time = 300 [20081019-10:17:03.890944258] ThreadGroup 0 [20081019-10:17:03.892593666] ================ [20081019-10:17:03.894607434] num_threads = 32 [20081019-10:17:03.896402379] [20081019-10:17:03.898164890] read_random = off [20081019-10:17:03.899854438] read_size = 36700160 (35MB) [20081019-10:17:03.901633007] read_blocksize = 4096 (4KB) [20081019-10:17:03.903339131] read_skip = off [20081019-10:17:03.905107648] read_skipsize = 0 (0B) [20081019-10:17:03.906789650] [20081019-10:17:03.908556016] write_random = off [20081019-10:17:03.910221103] write_size = 0 (0B) [20081019-10:17:03.911971351] fsync_file = 0 [20081019-10:17:03.913639311] write_blocksize = 0 (0B) [20081019-10:17:03.915423005] wait time = 0 [20081019-10:17:03.917108961] [20081019-10:17:03.918898356] op weights [20081019-10:17:03.920584201] read = 1 (100.00%) [20081019-10:17:03.922511169] readall = 0 (0.00%) [20081019-10:17:03.924674657] write = 0 (0.00%) [20081019-10:17:03.926706090] create = 0 (0.00%) [20081019-10:17:03.928651153] append = 0 (0.00%) [20081019-10:17:03.930490670] delete = 0 (0.00%) [20081019-10:17:03.932317599] metaop = 0 (0.00%) [20081019-10:17:03.934045483] createdir = 0 (0.00%) [20081019-10:17:03.935833899] stat = 0 (0.00%) [20081019-10:17:03.937545782] writeall = 0 (0.00%) [20081019-10:17:03.939330567] writeall_fsync = 0 (0.00%) [20081019-10:17:03.941020373] open_close = 0 (0.00%) [20081019-10:17:03.942824037] [20081019-10:17:03.944518397] FileSystem /mnt/ffsb1 [20081019-10:17:03.946286361] ========== [20081019-10:17:03.947933273] num_dirs = 0 [20081019-10:17:03.949785760] starting files = 1024 [20081019-10:17:03.951611415] [20081019-10:17:03.953340166] min file size = 36700160 (35MB) [20081019-10:17:03.955182187] max file size = 36700160 (35MB) [20081019-10:17:03.956955990] directio = off [20081019-10:17:03.958746278] alignedio = on [20081019-10:17:03.960478583] bufferedio = off [20081019-10:17:03.962246508] [20081019-10:17:03.963973531] aging is off [20081019-10:17:03.965769321] current utilization = 52.33% [20081019-10:17:03.967491533] [20081019-10:17:03.969245909] checking existing fs: /mnt/ffsb1 [20081019-10:17:04.037455831] fs setup took 0 secs [20081019-10:17:04.331309623] Syncing()...0 sec [20081019-10:17:04.333212182] Starting Actual Benchmark At: Sun Oct 19 10:17:04 2008 [20081019-10:17:04.346194327] [20081019-10:22:15.142002704] Syncing()...0 sec [20081019-10:22:15.175111186] FFSB benchmark finished at: Sun Oct 19 10:22:14 2008 [20081019-10:22:15.177661657] [20081019-10:22:15.180188289] Results: [20081019-10:22:15.207871224] Benchmark took 310.56 sec [20081019-10:22:15.210221055] [20081019-10:22:15.212666337] Total Results [20081019-10:22:15.226544810] =============== [20081019-10:22:15.228571553] Throughput: 19330.46 reads/sec -> 75.5MB/sec [20081019-10:22:15.230628346] 19330.46 Transactions per Second [20081019-10:22:15.232781610] [20081019-10:22:15.234789291] System Call Latency statistics in millisecs [20081019-10:22:15.237011149] ===== [20081019-10:22:15.239192616] Min Avg Max Total Calls [20081019-10:22:15.241361297] ======== ======== ======== ============ [20081019-10:22:15.243383025] [ open] 0.006000 8.558125 896.617981 670 [20081019-10:22:15.245630282] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:22:15.247656154] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081019-10:22:15.249642987] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081019-10:22:15.271333760] msec_range[3] 500.000000 - 1000.000000 : 7 [20081019-10:22:15.273287099] msec_range[4] 200.000000 - 500.000000 : 4 [20081019-10:22:15.275207485] msec_range[5] 100.000000 - 200.000000 : 1 [20081019-10:22:15.277269671] msec_range[6] 50.000000 - 100.000000 : 0 [20081019-10:22:15.279336624] msec_range[7] 20.000000 - 50.000000 : 1 [20081019-10:22:15.281309149] msec_range[8] 10.000000 - 20.000000 : 0 [20081019-10:22:15.283351388] msec_range[9] 5.000000 - 10.000000 : 1 [20081019-10:22:15.285309775] msec_range[10] 2.000000 - 5.000000 : 0 [20081019-10:22:15.287263417] msec_range[11] 1.000000 - 2.000000 : 0 [20081019-10:22:15.289160300] msec_range[12] 0.500000 - 1.000000 : 2 [20081019-10:22:15.291107484] msec_range[13] 0.200000 - 0.500000 : 0 [20081019-10:22:15.293114893] msec_range[14] 0.100000 - 0.200000 : 4 [20081019-10:22:15.295071476] msec_range[15] 0.050000 - 0.100000 : 44 [20081019-10:22:15.296956104] msec_range[16] 0.020000 - 0.050000 : 394 [20081019-10:22:15.298894868] msec_range[17] 0.010000 - 0.020000 : 186 [20081019-10:22:15.300931193] msec_range[18] 0.000000 - 0.010000 : 26 [20081019-10:22:15.302799484] [20081019-10:22:15.304813242] [ read] 0.001000 1.635239 3863.604004 6003200 [20081019-10:22:15.306783126] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:22:15.308799871] msec_range[1] 2000.000000 - 5000.000000 : 134 [20081019-10:22:15.310675347] msec_range[2] 1000.000000 - 2000.000000 : 1168 [20081019-10:22:15.312615967] msec_range[3] 500.000000 - 1000.000000 : 6079 [20081019-10:22:15.314605380] msec_range[4] 200.000000 - 500.000000 : 9847 [20081019-10:22:15.316559153] msec_range[5] 100.000000 - 200.000000 : 757 [20081019-10:22:15.318403110] msec_range[6] 50.000000 - 100.000000 : 406 [20081019-10:22:15.320339740] msec_range[7] 20.000000 - 50.000000 : 519 [20081019-10:22:15.322209063] msec_range[8] 10.000000 - 20.000000 : 412 [20081019-10:22:15.324163372] msec_range[9] 5.000000 - 10.000000 : 7507 [20081019-10:22:15.326024360] msec_range[10] 2.000000 - 5.000000 : 13772 [20081019-10:22:15.327977598] msec_range[11] 1.000000 - 2.000000 : 283 [20081019-10:22:15.329835316] msec_range[12] 0.500000 - 1.000000 : 631 [20081019-10:22:15.331699659] msec_range[13] 0.200000 - 0.500000 : 5548 [20081019-10:22:15.333639595] msec_range[14] 0.100000 - 0.200000 : 814 [20081019-10:22:15.335764372] msec_range[15] 0.050000 - 0.100000 : 1402 [20081019-10:22:15.337772626] msec_range[16] 0.020000 - 0.050000 : 12763 [20081019-10:22:15.339616146] msec_range[17] 0.010000 - 0.020000 : 114656 [20081019-10:22:15.342252584] msec_range[18] 0.000000 - 0.010000 : 5826502 [20081019-10:22:15.345327130] [20081019-10:22:15.347426265] [ close] 0.002000 0.006125 0.046000 670 [20081019-10:22:15.349712601] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:22:15.351819863] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081019-10:22:15.354004883] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081019-10:22:15.355957724] msec_range[3] 500.000000 - 1000.000000 : 0 [20081019-10:22:15.358040074] msec_range[4] 200.000000 - 500.000000 : 0 [20081019-10:22:15.360252651] msec_range[5] 100.000000 - 200.000000 : 0 [20081019-10:22:15.362466005] msec_range[6] 50.000000 - 100.000000 : 0 [20081019-10:22:15.364725446] msec_range[7] 20.000000 - 50.000000 : 0 [20081019-10:22:15.366869556] msec_range[8] 10.000000 - 20.000000 : 0 [20081019-10:22:15.369164058] msec_range[9] 5.000000 - 10.000000 : 0 [20081019-10:22:15.371221326] msec_range[10] 2.000000 - 5.000000 : 0 [20081019-10:22:15.373259600] msec_range[11] 1.000000 - 2.000000 : 0 [20081019-10:22:15.375156220] msec_range[12] 0.500000 - 1.000000 : 0 [20081019-10:22:15.377137983] msec_range[13] 0.200000 - 0.500000 : 0 [20081019-10:22:15.379078255] msec_range[14] 0.100000 - 0.200000 : 0 [20081019-10:22:15.381031582] msec_range[15] 0.050000 - 0.100000 : 0 [20081019-10:22:15.382916149] msec_range[16] 0.020000 - 0.050000 : 4 [20081019-10:22:15.384862574] msec_range[17] 0.010000 - 0.020000 : 21 [20081019-10:22:15.386792292] msec_range[18] 0.000000 - 0.010000 : 645 [20081019-10:22:15.388747617] [20081019-10:22:15.390648410] [20081019-10:22:15.392598681] [20081019-10:22:15.394471807] [20081019-10:22:15.396418435] 1.2% User Time [20081019-10:22:15.398266457] 15.1% System Time [20081019-10:22:15.400204496] 16.2% CPU Utilization [20081019-10:22:15.429625793] Profilers reporting [20081019-10:22:18.580537592] Profilers postprocessing [20081019-10:22:18.785216448] Stopping profiling. [20081019-10:22:18.789625797] Killing daemon. [20081019-10:22:19.059777647] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0032.08-10-19_10.16.54/analysis/oprofile.001 [20081019-10:22:19.062308930] Processing File : /autobench/logs/ffsb.sequential_reads__threads_0032.08-10-19_10.16.54/analysis/oprofile-brief.001 [20081019-10:22:19.255618545] Processing File : mpstat.001 [20081019-10:22:19.257798478] Discovered mpstat_interval=[5] [20081019-10:22:19.827894803] Processing Directory : sar.breakout.001 [20081019-10:22:19.830056079] Discovered sar_interval=[5] [20081019-10:22:20.084725735] Processing File : iostat.001 [20081019-10:22:20.087095579] Discovered iostat_interval=[5] [20081019-10:22:21.397773285] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-10-19_0957/ext3-baseline' [20081019-10:22:26.762302305] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081019-10:22:27.356450459] PROCESSING COMMAND : 'mount -t ext3 /dev/ffsbdev1 /mnt/ffsb1' [20081019-10:22:27.470404346] PROCESSING COMMAND : 'run random_reads__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb num_threads=1' [20081019-10:22:27.513397026] new log requested [20081019-10:22:27.567937893] Running command ffsb [20081019-10:22:35.486351657] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb [20081019-10:22:35.500995561] Importing argument : num_threads=1 [20081019-10:22:35.597414137] Checking for sar... [20081019-10:22:35.599607989] found [20081019-10:22:35.654887562] Checking for sar... [20081019-10:22:35.656994290] found [20081019-10:22:35.711847722] Checking for sar... [20081019-10:22:35.713778921] found [20081019-10:22:35.794694716] Checking for gettext... [20081019-10:22:35.809182443] found [20081019-10:22:35.811122734] Checking for libiberty... [20081019-10:22:35.821455956] found [20081019-10:22:35.823186426] Checking for popt... [20081019-10:22:35.827940713] found [20081019-10:22:35.835934037] Checking for popt64... [20081019-10:22:35.838129493] found [20081019-10:22:35.840211023] Checking for oprofile... [20081019-10:22:35.842164782] found [20081019-10:22:35.893112457] opcontrol: oprofile 0.9.3 compiled on Sep 18 2008 16:10:26 [20081019-10:22:35.971010235] Daemon not running [20081019-10:22:35.993196660] Unloading oprofile module [20081019-10:22:36.265707848] Daemon not running [20081019-10:22:36.696262521] Daemon not running [20081019-10:22:36.698357990] Separate options: none [20081019-10:22:36.700334400] vmlinux file: /boot/vmlinux-2.6.27-rc7 [20081019-10:22:36.702404304] Image filter: none [20081019-10:22:36.704331983] Call-graph depth: 0 [20081019-10:22:36.824839817] FFSB version 5.2.1 started [20081019-10:22:36.826941560] [20081019-10:22:36.828926899] benchmark time = 300 [20081019-10:22:36.830884817] ThreadGroup 0 [20081019-10:22:36.832756309] ================ [20081019-10:22:36.834472296] num_threads = 1 [20081019-10:22:36.836293985] [20081019-10:22:36.837982985] read_random = on [20081019-10:22:36.839728070] read_size = 1048576 (1MB) [20081019-10:22:36.841412425] read_blocksize = 4096 (4KB) [20081019-10:22:36.843299770] read_skip = off [20081019-10:22:36.844981480] read_skipsize = 0 (0B) [20081019-10:22:36.846718744] [20081019-10:22:36.848389002] write_random = off [20081019-10:22:36.850155801] write_size = 0 (0B) [20081019-10:22:36.851829058] fsync_file = 0 [20081019-10:22:36.853597204] write_blocksize = 0 (0B) [20081019-10:22:36.855262013] wait time = 0 [20081019-10:22:36.857185297] [20081019-10:22:36.859130432] op weights [20081019-10:22:36.861271851] read = 1 (100.00%) [20081019-10:22:36.863262920] readall = 0 (0.00%) [20081019-10:22:36.865187117] write = 0 (0.00%) [20081019-10:22:36.867003796] create = 0 (0.00%) [20081019-10:22:36.868734705] append = 0 (0.00%) [20081019-10:22:36.870591344] delete = 0 (0.00%) [20081019-10:22:36.872348290] metaop = 0 (0.00%) [20081019-10:22:36.874097761] createdir = 0 (0.00%) [20081019-10:22:36.875776239] stat = 0 (0.00%) [20081019-10:22:36.877570136] writeall = 0 (0.00%) [20081019-10:22:36.879262799] writeall_fsync = 0 (0.00%) [20081019-10:22:36.881005803] open_close = 0 (0.00%) [20081019-10:22:36.882701569] [20081019-10:22:36.884410572] FileSystem /mnt/ffsb1 [20081019-10:22:36.886181621] ========== [20081019-10:22:36.887955165] num_dirs = 0 [20081019-10:22:36.889649060] starting files = 1024 [20081019-10:22:36.891474126] [20081019-10:22:36.893202718] min file size = 36700160 (35MB) [20081019-10:22:36.894952731] max file size = 36700160 (35MB) [20081019-10:22:36.896674249] directio = off [20081019-10:22:36.898434408] alignedio = on [20081019-10:22:36.900126861] bufferedio = off [20081019-10:22:36.901856016] [20081019-10:22:36.903534987] aging is off [20081019-10:22:36.905284637] current utilization = 52.33% [20081019-10:22:36.907092997] [20081019-10:22:36.908756772] checking existing fs: /mnt/ffsb1 [20081019-10:22:36.968682087] fs setup took 0 secs [20081019-10:22:37.308661642] Syncing()...0 sec [20081019-10:22:37.310470820] Starting Actual Benchmark At: Sun Oct 19 10:22:37 2008 [20081019-10:22:37.322792842] [20081019-10:27:39.016237627] Syncing()...0 sec [20081019-10:27:39.019336761] FFSB benchmark finished at: Sun Oct 19 10:27:39 2008 [20081019-10:27:39.021907088] [20081019-10:27:39.023917150] Results: [20081019-10:27:39.038246166] Benchmark took 301.71 sec [20081019-10:27:39.040248816] [20081019-10:27:39.042402801] Total Results [20081019-10:27:39.056568824] =============== [20081019-10:27:39.059110023] Throughput: 330.07 reads/sec -> 1.29MB/sec [20081019-10:27:39.061320489] 330.07 Transactions per Second [20081019-10:27:39.064393116] [20081019-10:27:39.066604289] System Call Latency statistics in millisecs [20081019-10:27:39.068758995] ===== [20081019-10:27:39.071026727] Min Avg Max Total Calls [20081019-10:27:39.073219280] ======== ======== ======== ============ [20081019-10:27:39.076480089] [ open] 0.008000 0.012254 0.025000 389 [20081019-10:27:39.079382641] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:27:39.081913149] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081019-10:27:39.084103173] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081019-10:27:39.086424635] msec_range[3] 500.000000 - 1000.000000 : 0 [20081019-10:27:39.088697219] msec_range[4] 200.000000 - 500.000000 : 0 [20081019-10:27:39.090830870] msec_range[5] 100.000000 - 200.000000 : 0 [20081019-10:27:39.093135020] msec_range[6] 50.000000 - 100.000000 : 0 [20081019-10:27:39.095885831] msec_range[7] 20.000000 - 50.000000 : 0 [20081019-10:27:39.098223803] msec_range[8] 10.000000 - 20.000000 : 0 [20081019-10:27:39.100650009] msec_range[9] 5.000000 - 10.000000 : 0 [20081019-10:27:39.103052107] msec_range[10] 2.000000 - 5.000000 : 0 [20081019-10:27:39.105388626] msec_range[11] 1.000000 - 2.000000 : 0 [20081019-10:27:39.107836279] msec_range[12] 0.500000 - 1.000000 : 0 [20081019-10:27:39.110333567] msec_range[13] 0.200000 - 0.500000 : 0 [20081019-10:27:39.112573640] msec_range[14] 0.100000 - 0.200000 : 0 [20081019-10:27:39.114750977] msec_range[15] 0.050000 - 0.100000 : 0 [20081019-10:27:39.117126756] msec_range[16] 0.020000 - 0.050000 : 8 [20081019-10:27:39.119653308] msec_range[17] 0.010000 - 0.020000 : 376 [20081019-10:27:39.121825346] msec_range[18] 0.000000 - 0.010000 : 5 [20081019-10:27:39.124223401] [20081019-10:27:39.126489441] [ read] 0.002000 3.024555 96.785004 99584 [20081019-10:27:39.128818751] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:27:39.131043053] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081019-10:27:39.133190876] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081019-10:27:39.135522071] msec_range[3] 500.000000 - 1000.000000 : 0 [20081019-10:27:39.137712384] msec_range[4] 200.000000 - 500.000000 : 0 [20081019-10:27:39.140075383] msec_range[5] 100.000000 - 200.000000 : 0 [20081019-10:27:39.142170460] msec_range[6] 50.000000 - 100.000000 : 2 [20081019-10:27:39.144497823] msec_range[7] 20.000000 - 50.000000 : 37 [20081019-10:27:39.148666817] msec_range[8] 10.000000 - 20.000000 : 2468 [20081019-10:27:39.151251543] msec_range[9] 5.000000 - 10.000000 : 2397 [20081019-10:27:39.153547778] msec_range[10] 2.000000 - 5.000000 : 61178 [20081019-10:27:39.156246683] msec_range[11] 1.000000 - 2.000000 : 20060 [20081019-10:27:39.160182615] msec_range[12] 0.500000 - 1.000000 : 571 [20081019-10:27:39.162791893] msec_range[13] 0.200000 - 0.500000 : 10733 [20081019-10:27:39.165190829] msec_range[14] 0.100000 - 0.200000 : 298 [20081019-10:27:39.167415855] msec_range[15] 0.050000 - 0.100000 : 2 [20081019-10:27:39.169570815] msec_range[16] 0.020000 - 0.050000 : 7 [20081019-10:27:39.171966664] msec_range[17] 0.010000 - 0.020000 : 8 [20081019-10:27:39.174165727] msec_range[18] 0.000000 - 0.010000 : 1823 [20081019-10:27:39.177171445] [20081019-10:27:39.179462243] [ lseek] 0.000000 0.000982 0.028000 99584 [20081019-10:27:39.181885497] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:27:39.184197527] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081019-10:27:39.186527828] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081019-10:27:39.188676656] msec_range[3] 500.000000 - 1000.000000 : 0 [20081019-10:27:39.190922243] msec_range[4] 200.000000 - 500.000000 : 0 [20081019-10:27:39.193578830] msec_range[5] 100.000000 - 200.000000 : 0 [20081019-10:27:39.196027453] msec_range[6] 50.000000 - 100.000000 : 0 [20081019-10:27:39.199089736] msec_range[7] 20.000000 - 50.000000 : 0 [20081019-10:27:39.201575042] msec_range[8] 10.000000 - 20.000000 : 0 [20081019-10:27:39.203989941] msec_range[9] 5.000000 - 10.000000 : 0 [20081019-10:27:39.206301606] msec_range[10] 2.000000 - 5.000000 : 0 [20081019-10:27:39.208712916] msec_range[11] 1.000000 - 2.000000 : 0 [20081019-10:27:39.210961464] msec_range[12] 0.500000 - 1.000000 : 0 [20081019-10:27:39.213366834] msec_range[13] 0.200000 - 0.500000 : 0 [20081019-10:27:39.215580768] msec_range[14] 0.100000 - 0.200000 : 0 [20081019-10:27:39.217863200] msec_range[15] 0.050000 - 0.100000 : 0 [20081019-10:27:39.220357634] msec_range[16] 0.020000 - 0.050000 : 2 [20081019-10:27:39.222598778] msec_range[17] 0.010000 - 0.020000 : 9 [20081019-10:27:39.224817674] msec_range[18] 0.000000 - 0.010000 : 99573 [20081019-10:27:39.227011512] [20081019-10:27:39.229209530] [ close] 0.002000 0.003581 0.014000 389 [20081019-10:27:39.231552947] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:27:39.234085592] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081019-10:27:39.236194402] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081019-10:27:39.238302394] msec_range[3] 500.000000 - 1000.000000 : 0 [20081019-10:27:39.240411055] msec_range[4] 200.000000 - 500.000000 : 0 [20081019-10:27:39.242599820] msec_range[5] 100.000000 - 200.000000 : 0 [20081019-10:27:39.245276463] msec_range[6] 50.000000 - 100.000000 : 0 [20081019-10:27:39.247426519] msec_range[7] 20.000000 - 50.000000 : 0 [20081019-10:27:39.249634476] msec_range[8] 10.000000 - 20.000000 : 0 [20081019-10:27:39.252137906] msec_range[9] 5.000000 - 10.000000 : 0 [20081019-10:27:39.254524369] msec_range[10] 2.000000 - 5.000000 : 0 [20081019-10:27:39.256767570] msec_range[11] 1.000000 - 2.000000 : 0 [20081019-10:27:39.258981989] msec_range[12] 0.500000 - 1.000000 : 0 [20081019-10:27:39.261178823] msec_range[13] 0.200000 - 0.500000 : 0 [20081019-10:27:39.263284095] msec_range[14] 0.100000 - 0.200000 : 0 [20081019-10:27:39.266061118] msec_range[15] 0.050000 - 0.100000 : 0 [20081019-10:27:39.268875085] msec_range[16] 0.020000 - 0.050000 : 0 [20081019-10:27:39.271025403] msec_range[17] 0.010000 - 0.020000 : 1 [20081019-10:27:39.274653670] msec_range[18] 0.000000 - 0.010000 : 388 [20081019-10:27:39.276977718] [20081019-10:27:39.279248121] [20081019-10:27:39.281613177] [20081019-10:27:39.283867854] [20081019-10:27:39.286204048] 0.1% User Time [20081019-10:27:39.288513483] 0.8% System Time [20081019-10:27:39.290911112] 0.8% CPU Utilization [20081019-10:27:39.293099982] Profilers reporting [20081019-10:27:39.578212363] Profilers postprocessing [20081019-10:27:39.762465671] Stopping profiling. [20081019-10:27:39.766916591] Killing daemon. [20081019-10:27:40.935396076] Processing File : /autobench/logs/ffsb.random_reads__threads_0001.08-10-19_10.22.27/analysis/oprofile.001 [20081019-10:27:40.937520349] Processing File : /autobench/logs/ffsb.random_reads__threads_0001.08-10-19_10.22.27/analysis/oprofile-brief.001 [20081019-10:27:41.047417578] Processing File : mpstat.001 [20081019-10:27:41.049360350] Discovered mpstat_interval=[5] [20081019-10:27:41.561779736] Processing Directory : sar.breakout.001 [20081019-10:27:41.564020757] Discovered sar_interval=[5] [20081019-10:27:41.679411948] Processing File : iostat.001 [20081019-10:27:41.681568828] Discovered iostat_interval=[5] [20081019-10:27:42.059588937] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-10-19_0957/ext3-baseline' [20081019-10:27:46.927605055] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081019-10:27:47.194493662] PROCESSING COMMAND : 'mount -t ext3 /dev/ffsbdev1 /mnt/ffsb1' [20081019-10:27:47.441130054] PROCESSING COMMAND : 'run random_reads__threads_0008 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb num_threads=8' [20081019-10:27:47.488032490] new log requested [20081019-10:27:47.517128603] Running command ffsb [20081019-10:27:54.621720378] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb [20081019-10:27:54.626996555] Importing argument : num_threads=8 [20081019-10:27:54.717868517] Checking for sar... [20081019-10:27:54.720060024] found [20081019-10:27:54.775917499] Checking for sar... [20081019-10:27:54.778205378] found [20081019-10:27:54.833629087] Checking for sar... [20081019-10:27:54.836048413] found [20081019-10:27:54.910282375] Checking for gettext... [20081019-10:27:54.912528861] found [20081019-10:27:54.914628947] Checking for libiberty... [20081019-10:27:54.916576627] found [20081019-10:27:54.918472401] Checking for popt... [20081019-10:27:54.920430326] found [20081019-10:27:54.922262386] Checking for popt64... [20081019-10:27:54.924201631] found [20081019-10:27:54.926186283] Checking for oprofile... [20081019-10:27:54.928297240] found [20081019-10:27:54.975382128] opcontrol: oprofile 0.9.3 compiled on Sep 18 2008 16:10:26 [20081019-10:27:55.054716189] Daemon not running [20081019-10:27:55.064465736] Unloading oprofile module [20081019-10:27:55.172622053] Daemon not running [20081019-10:27:55.473851832] Daemon not running [20081019-10:27:55.475809366] Separate options: none [20081019-10:27:55.478691298] vmlinux file: /boot/vmlinux-2.6.27-rc7 [20081019-10:27:55.480750693] Image filter: none [20081019-10:27:55.482714736] Call-graph depth: 0 [20081019-10:27:55.578176022] FFSB version 5.2.1 started [20081019-10:27:55.580389603] [20081019-10:27:55.609216115] benchmark time = 300 [20081019-10:27:55.611377703] ThreadGroup 0 [20081019-10:27:55.613250623] ================ [20081019-10:27:55.615407058] num_threads = 8 [20081019-10:27:55.617233430] [20081019-10:27:55.619016589] read_random = on [20081019-10:27:55.620735142] read_size = 1048576 (1MB) [20081019-10:27:55.622520882] read_blocksize = 4096 (4KB) [20081019-10:27:55.624220693] read_skip = off [20081019-10:27:55.625989510] read_skipsize = 0 (0B) [20081019-10:27:55.627678692] [20081019-10:27:55.629475444] write_random = off [20081019-10:27:55.631309603] write_size = 0 (0B) [20081019-10:27:55.633252114] fsync_file = 0 [20081019-10:27:55.635345042] write_blocksize = 0 (0B) [20081019-10:27:55.637182417] wait time = 0 [20081019-10:27:55.638962661] [20081019-10:27:55.640617626] op weights [20081019-10:27:55.642441962] read = 1 (100.00%) [20081019-10:27:55.644139131] readall = 0 (0.00%) [20081019-10:27:55.645906769] write = 0 (0.00%) [20081019-10:27:55.647669969] create = 0 (0.00%) [20081019-10:27:55.649449112] append = 0 (0.00%) [20081019-10:27:55.651131625] delete = 0 (0.00%) [20081019-10:27:55.652899891] metaop = 0 (0.00%) [20081019-10:27:55.654601640] createdir = 0 (0.00%) [20081019-10:27:55.656380714] stat = 0 (0.00%) [20081019-10:27:55.658052656] writeall = 0 (0.00%) [20081019-10:27:55.659793169] writeall_fsync = 0 (0.00%) [20081019-10:27:55.661515988] open_close = 0 (0.00%) [20081019-10:27:55.663257869] [20081019-10:27:55.664941518] FileSystem /mnt/ffsb1 [20081019-10:27:55.666680889] ========== [20081019-10:27:55.668359694] num_dirs = 0 [20081019-10:27:55.670092807] starting files = 1024 [20081019-10:27:55.671753162] [20081019-10:27:55.673513925] min file size = 36700160 (35MB) [20081019-10:27:55.675272736] max file size = 36700160 (35MB) [20081019-10:27:55.677020207] directio = off [20081019-10:27:55.678689081] alignedio = on [20081019-10:27:55.680445857] bufferedio = off [20081019-10:27:55.682157042] [20081019-10:27:55.684366954] aging is off [20081019-10:27:55.686241816] current utilization = 52.33% [20081019-10:27:55.688547396] [20081019-10:27:55.690514363] checking existing fs: /mnt/ffsb1 [20081019-10:27:55.766953802] fs setup took 0 secs [20081019-10:27:56.084698962] Syncing()...0 sec [20081019-10:27:56.086523357] Starting Actual Benchmark At: Sun Oct 19 10:27:56 2008 [20081019-10:27:56.099551034] [20081019-10:33:00.114986978] Syncing()...0 sec [20081019-10:33:00.117625826] FFSB benchmark finished at: Sun Oct 19 10:33:00 2008 [20081019-10:33:00.120137847] [20081019-10:33:00.122522945] Results: [20081019-10:33:00.136174075] Benchmark took 304.03 sec [20081019-10:33:00.138193531] [20081019-10:33:00.140387410] Total Results [20081019-10:33:00.153697294] =============== [20081019-10:33:00.156058514] Throughput: 389.86 reads/sec -> 1.52MB/sec [20081019-10:33:00.158474096] 389.86 Transactions per Second [20081019-10:33:00.160919002] [20081019-10:33:00.163183357] System Call Latency statistics in millisecs [20081019-10:33:00.165379073] ===== [20081019-10:33:00.167460570] Min Avg Max Total Calls [20081019-10:33:00.169950393] ======== ======== ======== ============ [20081019-10:33:00.172996404] [ open] 0.006000 0.012743 0.041000 463 [20081019-10:33:00.175307830] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:33:00.177498895] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081019-10:33:00.180459485] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081019-10:33:00.182747119] msec_range[3] 500.000000 - 1000.000000 : 0 [20081019-10:33:00.184967393] msec_range[4] 200.000000 - 500.000000 : 0 [20081019-10:33:00.187120009] msec_range[5] 100.000000 - 200.000000 : 0 [20081019-10:33:00.189552421] msec_range[6] 50.000000 - 100.000000 : 0 [20081019-10:33:00.192530902] msec_range[7] 20.000000 - 50.000000 : 0 [20081019-10:33:00.194880710] msec_range[8] 10.000000 - 20.000000 : 0 [20081019-10:33:00.197039666] msec_range[9] 5.000000 - 10.000000 : 0 [20081019-10:33:00.199521514] msec_range[10] 2.000000 - 5.000000 : 0 [20081019-10:33:00.202047765] msec_range[11] 1.000000 - 2.000000 : 0 [20081019-10:33:00.204375587] msec_range[12] 0.500000 - 1.000000 : 0 [20081019-10:33:00.206465768] msec_range[13] 0.200000 - 0.500000 : 0 [20081019-10:33:00.208703971] msec_range[14] 0.100000 - 0.200000 : 0 [20081019-10:33:00.210974127] msec_range[15] 0.050000 - 0.100000 : 0 [20081019-10:33:00.213466457] msec_range[16] 0.020000 - 0.050000 : 23 [20081019-10:33:00.215305842] msec_range[17] 0.010000 - 0.020000 : 311 [20081019-10:33:00.217308038] msec_range[18] 0.000000 - 0.010000 : 129 [20081019-10:33:00.219576317] [20081019-10:33:00.222853210] [ read] 0.002000 20.393136 2009.943970 118528 [20081019-10:33:00.225097757] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:33:00.227481002] msec_range[1] 2000.000000 - 5000.000000 : 6 [20081019-10:33:00.229691650] msec_range[2] 1000.000000 - 2000.000000 : 50 [20081019-10:33:00.232012176] msec_range[3] 500.000000 - 1000.000000 : 302 [20081019-10:33:00.234846284] msec_range[4] 200.000000 - 500.000000 : 1512 [20081019-10:33:00.236915860] msec_range[5] 100.000000 - 200.000000 : 2527 [20081019-10:33:00.239355627] msec_range[6] 50.000000 - 100.000000 : 4964 [20081019-10:33:00.241523106] msec_range[7] 20.000000 - 50.000000 : 14295 [20081019-10:33:00.243756578] msec_range[8] 10.000000 - 20.000000 : 18003 [20081019-10:33:00.246155541] msec_range[9] 5.000000 - 10.000000 : 19323 [20081019-10:33:00.249059155] msec_range[10] 2.000000 - 5.000000 : 38538 [20081019-10:33:00.251259326] msec_range[11] 1.000000 - 2.000000 : 15496 [20081019-10:33:00.254400419] msec_range[12] 0.500000 - 1.000000 : 494 [20081019-10:33:00.257009813] msec_range[13] 0.200000 - 0.500000 : 674 [20081019-10:33:00.259745991] msec_range[14] 0.100000 - 0.200000 : 21 [20081019-10:33:00.262312934] msec_range[15] 0.050000 - 0.100000 : 0 [20081019-10:33:00.264634756] msec_range[16] 0.020000 - 0.050000 : 0 [20081019-10:33:00.267203515] msec_range[17] 0.010000 - 0.020000 : 26 [20081019-10:33:00.269814361] msec_range[18] 0.000000 - 0.010000 : 2297 [20081019-10:33:00.272559870] [20081019-10:33:00.274790193] [ lseek] 0.000000 0.001059 0.176000 118528 [20081019-10:33:00.277040342] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:33:00.279262923] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081019-10:33:00.281391781] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081019-10:33:00.283325138] msec_range[3] 500.000000 - 1000.000000 : 0 [20081019-10:33:00.285579702] msec_range[4] 200.000000 - 500.000000 : 0 [20081019-10:33:00.287866449] msec_range[5] 100.000000 - 200.000000 : 0 [20081019-10:33:00.291739651] msec_range[6] 50.000000 - 100.000000 : 0 [20081019-10:33:00.294286760] msec_range[7] 20.000000 - 50.000000 : 0 [20081019-10:33:00.296543908] msec_range[8] 10.000000 - 20.000000 : 0 [20081019-10:33:00.298941908] msec_range[9] 5.000000 - 10.000000 : 0 [20081019-10:33:00.301502370] msec_range[10] 2.000000 - 5.000000 : 0 [20081019-10:33:00.304507709] msec_range[11] 1.000000 - 2.000000 : 0 [20081019-10:33:00.306860115] msec_range[12] 0.500000 - 1.000000 : 0 [20081019-10:33:00.309575804] msec_range[13] 0.200000 - 0.500000 : 0 [20081019-10:33:00.311988134] msec_range[14] 0.100000 - 0.200000 : 1 [20081019-10:33:00.314846583] msec_range[15] 0.050000 - 0.100000 : 0 [20081019-10:33:00.317186638] msec_range[16] 0.020000 - 0.050000 : 0 [20081019-10:33:00.319358795] msec_range[17] 0.010000 - 0.020000 : 15 [20081019-10:33:00.321503999] msec_range[18] 0.000000 - 0.010000 : 118512 [20081019-10:33:00.323481428] [20081019-10:33:00.325526300] [ close] 0.001000 0.004056 0.011000 463 [20081019-10:33:00.327541714] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:33:00.329799589] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081019-10:33:00.332068725] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081019-10:33:00.334135252] msec_range[3] 500.000000 - 1000.000000 : 0 [20081019-10:33:00.336121869] msec_range[4] 200.000000 - 500.000000 : 0 [20081019-10:33:00.338025556] msec_range[5] 100.000000 - 200.000000 : 0 [20081019-10:33:00.340435551] msec_range[6] 50.000000 - 100.000000 : 0 [20081019-10:33:00.342764258] msec_range[7] 20.000000 - 50.000000 : 0 [20081019-10:33:00.344974383] msec_range[8] 10.000000 - 20.000000 : 0 [20081019-10:33:00.347357790] msec_range[9] 5.000000 - 10.000000 : 0 [20081019-10:33:00.349771327] msec_range[10] 2.000000 - 5.000000 : 0 [20081019-10:33:00.354398028] msec_range[11] 1.000000 - 2.000000 : 0 [20081019-10:33:00.357170292] msec_range[12] 0.500000 - 1.000000 : 0 [20081019-10:33:00.360120504] msec_range[13] 0.200000 - 0.500000 : 0 [20081019-10:33:00.362697724] msec_range[14] 0.100000 - 0.200000 : 0 [20081019-10:33:00.365326849] msec_range[15] 0.050000 - 0.100000 : 0 [20081019-10:33:00.368075092] msec_range[16] 0.020000 - 0.050000 : 0 [20081019-10:33:00.370629702] msec_range[17] 0.010000 - 0.020000 : 2 [20081019-10:33:00.372891420] msec_range[18] 0.000000 - 0.010000 : 461 [20081019-10:33:00.375284222] [20081019-10:33:00.377498547] [20081019-10:33:00.379863189] [20081019-10:33:00.383004835] [20081019-10:33:00.385301309] 0.1% User Time [20081019-10:33:00.387775648] 1.1% System Time [20081019-10:33:00.390139914] 1.2% CPU Utilization [20081019-10:33:00.392301396] Profilers reporting [20081019-10:33:00.800555855] Profilers postprocessing [20081019-10:33:00.983621510] Stopping profiling. [20081019-10:33:00.988065419] Killing daemon. [20081019-10:33:02.160340267] Processing File : /autobench/logs/ffsb.random_reads__threads_0008.08-10-19_10.27.47/analysis/oprofile.001 [20081019-10:33:02.162373041] Processing File : /autobench/logs/ffsb.random_reads__threads_0008.08-10-19_10.27.47/analysis/oprofile-brief.001 [20081019-10:33:02.274983745] Processing File : mpstat.001 [20081019-10:33:02.277160722] Discovered mpstat_interval=[5] [20081019-10:33:02.792501473] Processing Directory : sar.breakout.001 [20081019-10:33:02.794728385] Discovered sar_interval=[5] [20081019-10:33:02.911628139] Processing File : iostat.001 [20081019-10:33:02.913667804] Discovered iostat_interval=[5] [20081019-10:33:03.299759719] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-10-19_0957/ext3-baseline' [20081019-10:33:09.564963906] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081019-10:33:09.876716837] PROCESSING COMMAND : 'mount -t ext3 /dev/ffsbdev1 /mnt/ffsb1' [20081019-10:33:10.075100834] PROCESSING COMMAND : 'run random_reads__threads_0032 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb num_threads=32' [20081019-10:33:10.118039711] new log requested [20081019-10:33:10.140479931] Running command ffsb [20081019-10:33:17.263290004] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_reads.ffsb [20081019-10:33:17.268422241] Importing argument : num_threads=32 [20081019-10:33:17.359130771] Checking for sar... [20081019-10:33:17.361455647] found [20081019-10:33:17.417364923] Checking for sar... [20081019-10:33:17.419750451] found [20081019-10:33:17.474867375] Checking for sar... [20081019-10:33:17.477068105] found [20081019-10:33:17.550471541] Checking for gettext... [20081019-10:33:17.553184271] found [20081019-10:33:17.555185027] Checking for libiberty... [20081019-10:33:17.557169040] found [20081019-10:33:17.559225169] Checking for popt... [20081019-10:33:17.561178340] found [20081019-10:33:17.563037438] Checking for popt64... [20081019-10:33:17.564960228] found [20081019-10:33:17.566876475] Checking for oprofile... [20081019-10:33:17.568881914] found [20081019-10:33:17.614926964] opcontrol: oprofile 0.9.3 compiled on Sep 18 2008 16:10:26 [20081019-10:33:17.692224660] Daemon not running [20081019-10:33:17.701964549] Unloading oprofile module [20081019-10:33:17.803694802] Daemon not running [20081019-10:33:18.096775879] Daemon not running [20081019-10:33:18.098772090] Separate options: none [20081019-10:33:18.100818252] vmlinux file: /boot/vmlinux-2.6.27-rc7 [20081019-10:33:18.102727221] Image filter: none [20081019-10:33:18.104638371] Call-graph depth: 0 [20081019-10:33:18.202408857] FFSB version 5.2.1 started [20081019-10:33:18.204501248] [20081019-10:33:18.323941362] benchmark time = 300 [20081019-10:33:18.325953874] ThreadGroup 0 [20081019-10:33:18.328003990] ================ [20081019-10:33:18.329869890] num_threads = 32 [20081019-10:33:18.331718061] [20081019-10:33:18.333435444] read_random = on [20081019-10:33:18.335222707] read_size = 1048576 (1MB) [20081019-10:33:18.336930253] read_blocksize = 4096 (4KB) [20081019-10:33:18.338682016] read_skip = off [20081019-10:33:18.340369327] read_skipsize = 0 (0B) [20081019-10:33:18.342117828] [20081019-10:33:18.343789585] write_random = off [20081019-10:33:18.345542440] write_size = 0 (0B) [20081019-10:33:18.347248690] fsync_file = 0 [20081019-10:33:18.349065725] write_blocksize = 0 (0B) [20081019-10:33:18.350750488] wait time = 0 [20081019-10:33:18.352523516] [20081019-10:33:18.354241095] op weights [20081019-10:33:18.356120624] read = 1 (100.00%) [20081019-10:33:18.357875723] readall = 0 (0.00%) [20081019-10:33:18.359612282] write = 0 (0.00%) [20081019-10:33:18.361304905] create = 0 (0.00%) [20081019-10:33:18.363271278] append = 0 (0.00%) [20081019-10:33:18.365259212] delete = 0 (0.00%) [20081019-10:33:18.367401171] metaop = 0 (0.00%) [20081019-10:33:18.369348842] createdir = 0 (0.00%) [20081019-10:33:18.371282049] stat = 0 (0.00%) [20081019-10:33:18.373004672] writeall = 0 (0.00%) [20081019-10:33:18.374810026] writeall_fsync = 0 (0.00%) [20081019-10:33:18.376564252] open_close = 0 (0.00%) [20081019-10:33:18.378380140] [20081019-10:33:18.380184015] FileSystem /mnt/ffsb1 [20081019-10:33:18.381883341] ========== [20081019-10:33:18.383750005] num_dirs = 0 [20081019-10:33:18.385506327] starting files = 1024 [20081019-10:33:18.387290614] [20081019-10:33:18.389001100] min file size = 36700160 (35MB) [20081019-10:33:18.390801756] max file size = 36700160 (35MB) [20081019-10:33:18.392528072] directio = off [20081019-10:33:18.394302140] alignedio = on [20081019-10:33:18.396000453] bufferedio = off [20081019-10:33:18.397815141] [20081019-10:33:18.399528786] aging is off [20081019-10:33:18.401292414] current utilization = 52.33% [20081019-10:33:18.402991638] [20081019-10:33:18.404763092] checking existing fs: /mnt/ffsb1 [20081019-10:33:18.464953944] fs setup took 0 secs [20081019-10:33:18.797112207] Syncing()...0 sec [20081019-10:33:18.798978613] Starting Actual Benchmark At: Sun Oct 19 10:33:18 2008 [20081019-10:33:18.811791022] [20081019-10:38:28.705695021] Syncing()...0 sec [20081019-10:38:28.708393156] FFSB benchmark finished at: Sun Oct 19 10:38:28 2008 [20081019-10:38:28.711031203] [20081019-10:38:28.713077005] Results: [20081019-10:38:28.727357555] Benchmark took 309.91 sec [20081019-10:38:28.729576587] [20081019-10:38:28.731870681] Total Results [20081019-10:38:28.745819071] =============== [20081019-10:38:28.749079890] Throughput: 479.94 reads/sec -> 1.87MB/sec [20081019-10:38:28.751565107] 479.94 Transactions per Second [20081019-10:38:28.753912568] [20081019-10:38:28.755996756] System Call Latency statistics in millisecs [20081019-10:38:28.758371735] ===== [20081019-10:38:28.760768515] Min Avg Max Total Calls [20081019-10:38:28.763166147] ======== ======== ======== ============ [20081019-10:38:28.765795319] [ open] 0.006000 0.013664 0.346000 581 [20081019-10:38:28.768303201] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:38:28.770566897] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081019-10:38:28.772794946] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081019-10:38:28.775200529] msec_range[3] 500.000000 - 1000.000000 : 0 [20081019-10:38:28.777562703] msec_range[4] 200.000000 - 500.000000 : 0 [20081019-10:38:28.779757257] msec_range[5] 100.000000 - 200.000000 : 0 [20081019-10:38:28.782162676] msec_range[6] 50.000000 - 100.000000 : 0 [20081019-10:38:28.784436188] msec_range[7] 20.000000 - 50.000000 : 0 [20081019-10:38:28.787858551] msec_range[8] 10.000000 - 20.000000 : 0 [20081019-10:38:28.790245055] msec_range[9] 5.000000 - 10.000000 : 0 [20081019-10:38:28.793742755] msec_range[10] 2.000000 - 5.000000 : 0 [20081019-10:38:28.796185618] msec_range[11] 1.000000 - 2.000000 : 0 [20081019-10:38:28.799490900] msec_range[12] 0.500000 - 1.000000 : 0 [20081019-10:38:28.801901037] msec_range[13] 0.200000 - 0.500000 : 1 [20081019-10:38:28.804182533] msec_range[14] 0.100000 - 0.200000 : 0 [20081019-10:38:28.806662196] msec_range[15] 0.050000 - 0.100000 : 0 [20081019-10:38:28.809437335] msec_range[16] 0.020000 - 0.050000 : 63 [20081019-10:38:28.812677949] msec_range[17] 0.010000 - 0.020000 : 350 [20081019-10:38:28.815111187] msec_range[18] 0.000000 - 0.010000 : 167 [20081019-10:38:28.817535840] [20081019-10:38:28.820067703] [ read] 0.001000 65.845576 4016.608887 148736 [20081019-10:38:28.822295509] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:38:28.824513933] msec_range[1] 2000.000000 - 5000.000000 : 447 [20081019-10:38:28.826660143] msec_range[2] 1000.000000 - 2000.000000 : 2014 [20081019-10:38:28.828903214] msec_range[3] 500.000000 - 1000.000000 : 1357 [20081019-10:38:28.831475697] msec_range[4] 200.000000 - 500.000000 : 3197 [20081019-10:38:28.833919614] msec_range[5] 100.000000 - 200.000000 : 7825 [20081019-10:38:28.838178359] msec_range[6] 50.000000 - 100.000000 : 15646 [20081019-10:38:28.840604752] msec_range[7] 20.000000 - 50.000000 : 30902 [20081019-10:38:28.843117105] msec_range[8] 10.000000 - 20.000000 : 26307 [20081019-10:38:28.845514196] msec_range[9] 5.000000 - 10.000000 : 25124 [20081019-10:38:28.848074154] msec_range[10] 2.000000 - 5.000000 : 25170 [20081019-10:38:28.850957389] msec_range[11] 1.000000 - 2.000000 : 7360 [20081019-10:38:28.853498202] msec_range[12] 0.500000 - 1.000000 : 136 [20081019-10:38:28.855923410] msec_range[13] 0.200000 - 0.500000 : 64 [20081019-10:38:28.858337288] msec_range[14] 0.100000 - 0.200000 : 0 [20081019-10:38:28.860988763] msec_range[15] 0.050000 - 0.100000 : 0 [20081019-10:38:28.863375158] msec_range[16] 0.020000 - 0.050000 : 0 [20081019-10:38:28.865811035] msec_range[17] 0.010000 - 0.020000 : 56 [20081019-10:38:28.868780872] msec_range[18] 0.000000 - 0.010000 : 3131 [20081019-10:38:28.871284448] [20081019-10:38:28.873767694] [ lseek] 0.000000 0.001117 0.025000 148736 [20081019-10:38:28.875979295] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:38:28.878191631] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081019-10:38:28.881235060] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081019-10:38:28.883703432] msec_range[3] 500.000000 - 1000.000000 : 0 [20081019-10:38:28.886054865] msec_range[4] 200.000000 - 500.000000 : 0 [20081019-10:38:28.889194647] msec_range[5] 100.000000 - 200.000000 : 0 [20081019-10:38:28.891680078] msec_range[6] 50.000000 - 100.000000 : 0 [20081019-10:38:28.894025956] msec_range[7] 20.000000 - 50.000000 : 0 [20081019-10:38:28.896352242] msec_range[8] 10.000000 - 20.000000 : 0 [20081019-10:38:28.898676681] msec_range[9] 5.000000 - 10.000000 : 0 [20081019-10:38:28.900900923] msec_range[10] 2.000000 - 5.000000 : 0 [20081019-10:38:28.903402636] msec_range[11] 1.000000 - 2.000000 : 0 [20081019-10:38:28.906736854] msec_range[12] 0.500000 - 1.000000 : 0 [20081019-10:38:28.908755889] msec_range[13] 0.200000 - 0.500000 : 0 [20081019-10:38:28.910916399] msec_range[14] 0.100000 - 0.200000 : 0 [20081019-10:38:28.913266711] msec_range[15] 0.050000 - 0.100000 : 0 [20081019-10:38:28.915988065] msec_range[16] 0.020000 - 0.050000 : 1 [20081019-10:38:28.918064522] msec_range[17] 0.010000 - 0.020000 : 20 [20081019-10:38:28.920165625] msec_range[18] 0.000000 - 0.010000 : 148715 [20081019-10:38:28.922392111] [20081019-10:38:28.924687150] [ close] 0.002000 0.003976 0.010000 581 [20081019-10:38:28.926916782] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:38:28.928898776] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081019-10:38:28.931098674] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081019-10:38:28.933241564] msec_range[3] 500.000000 - 1000.000000 : 0 [20081019-10:38:28.935126035] msec_range[4] 200.000000 - 500.000000 : 0 [20081019-10:38:28.937267836] msec_range[5] 100.000000 - 200.000000 : 0 [20081019-10:38:28.939290508] msec_range[6] 50.000000 - 100.000000 : 0 [20081019-10:38:28.941284051] msec_range[7] 20.000000 - 50.000000 : 0 [20081019-10:38:28.943202377] msec_range[8] 10.000000 - 20.000000 : 0 [20081019-10:38:28.945232644] msec_range[9] 5.000000 - 10.000000 : 0 [20081019-10:38:28.947258502] msec_range[10] 2.000000 - 5.000000 : 0 [20081019-10:38:28.949173272] msec_range[11] 1.000000 - 2.000000 : 0 [20081019-10:38:28.951191771] msec_range[12] 0.500000 - 1.000000 : 0 [20081019-10:38:28.953136604] msec_range[13] 0.200000 - 0.500000 : 0 [20081019-10:38:28.955069833] msec_range[14] 0.100000 - 0.200000 : 0 [20081019-10:38:28.956933449] msec_range[15] 0.050000 - 0.100000 : 0 [20081019-10:38:28.958978018] msec_range[16] 0.020000 - 0.050000 : 0 [20081019-10:38:28.960987081] msec_range[17] 0.010000 - 0.020000 : 2 [20081019-10:38:28.962902230] msec_range[18] 0.000000 - 0.010000 : 579 [20081019-10:38:28.964900772] [20081019-10:38:28.966851400] [20081019-10:38:28.968822450] [20081019-10:38:28.970688422] [20081019-10:38:28.972647446] 0.1% User Time [20081019-10:38:28.974526110] 1.4% System Time [20081019-10:38:28.976461103] 1.4% CPU Utilization [20081019-10:38:28.978328632] Profilers reporting [20081019-10:38:29.269704021] Profilers postprocessing [20081019-10:38:30.474387757] Stopping profiling. [20081019-10:38:30.480064837] Killing daemon. [20081019-10:38:31.649335574] Processing File : /autobench/logs/ffsb.random_reads__threads_0032.08-10-19_10.33.10/analysis/oprofile.001 [20081019-10:38:31.651443918] Processing File : /autobench/logs/ffsb.random_reads__threads_0032.08-10-19_10.33.10/analysis/oprofile-brief.001 [20081019-10:38:31.761824014] Processing File : mpstat.001 [20081019-10:38:31.763960256] Discovered mpstat_interval=[5] [20081019-10:38:32.282995648] Processing Directory : sar.breakout.001 [20081019-10:38:32.285246748] Discovered sar_interval=[5] [20081019-10:38:32.402462206] Processing File : iostat.001 [20081019-10:38:32.404760596] Discovered iostat_interval=[5] [20081019-10:38:32.789630602] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-10-19_0957/ext3-baseline' [20081019-10:38:40.180593851] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081019-10:38:40.615360073] PROCESSING COMMAND : 'mount -t ext3 /dev/ffsbdev1 /mnt/ffsb1' [20081019-10:38:40.807203270] PROCESSING COMMAND : 'run random_writes__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb num_threads=1' [20081019-10:38:40.857556193] new log requested [20081019-10:38:40.879672341] Running command ffsb [20081019-10:38:48.010535113] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb [20081019-10:38:48.018994218] Importing argument : num_threads=1 [20081019-10:38:48.109131328] Checking for sar... [20081019-10:38:48.111456656] found [20081019-10:38:48.167466752] Checking for sar... [20081019-10:38:48.169537218] found [20081019-10:38:48.224457107] Checking for sar... [20081019-10:38:48.226600917] found [20081019-10:38:48.301635535] Checking for gettext... [20081019-10:38:48.303846029] found [20081019-10:38:48.305799671] Checking for libiberty... [20081019-10:38:48.307939788] found [20081019-10:38:48.310006988] Checking for popt... [20081019-10:38:48.311892053] found [20081019-10:38:48.313719695] Checking for popt64... [20081019-10:38:48.315591938] found [20081019-10:38:48.317461000] Checking for oprofile... [20081019-10:38:48.319316834] found [20081019-10:38:48.366586637] opcontrol: oprofile 0.9.3 compiled on Sep 18 2008 16:10:26 [20081019-10:38:48.444520797] Daemon not running [20081019-10:38:48.454298382] Unloading oprofile module [20081019-10:38:48.557721695] Daemon not running [20081019-10:38:48.856169153] Daemon not running [20081019-10:38:48.858139954] Separate options: none [20081019-10:38:48.860310062] vmlinux file: /boot/vmlinux-2.6.27-rc7 [20081019-10:38:48.862347687] Image filter: none [20081019-10:38:48.864392010] Call-graph depth: 0 [20081019-10:38:48.959345519] FFSB version 5.2.1 started [20081019-10:38:48.961409397] [20081019-10:38:48.963579595] benchmark time = 300 [20081019-10:38:48.965545227] ThreadGroup 0 [20081019-10:38:48.967425516] ================ [20081019-10:38:48.969120804] num_threads = 1 [20081019-10:38:48.970899642] [20081019-10:38:48.972588695] read_random = off [20081019-10:38:48.974379891] read_size = 0 (0B) [20081019-10:38:48.976478447] read_blocksize = 0 (0B) [20081019-10:38:48.978341600] read_skip = off [20081019-10:38:48.980412680] read_skipsize = 0 (0B) [20081019-10:38:48.982315378] [20081019-10:38:48.984185474] write_random = on [20081019-10:38:48.985876296] write_size = 1048576 (1MB) [20081019-10:38:48.987679360] fsync_file = 0 [20081019-10:38:48.989395464] write_blocksize = 4096 (4KB) [20081019-10:38:48.991161645] wait time = 0 [20081019-10:38:48.992889285] [20081019-10:38:48.994702966] op weights [20081019-10:38:48.996525820] read = 0 (0.00%) [20081019-10:38:48.998271397] readall = 0 (0.00%) [20081019-10:38:49.000113996] write = 1 (100.00%) [20081019-10:38:49.001905954] create = 0 (0.00%) [20081019-10:38:49.003687156] append = 0 (0.00%) [20081019-10:38:49.005384493] delete = 0 (0.00%) [20081019-10:38:49.007150408] metaop = 0 (0.00%) [20081019-10:38:49.008863118] createdir = 0 (0.00%) [20081019-10:38:49.010671362] stat = 0 (0.00%) [20081019-10:38:49.012376423] writeall = 0 (0.00%) [20081019-10:38:49.014178830] writeall_fsync = 0 (0.00%) [20081019-10:38:49.015877035] open_close = 0 (0.00%) [20081019-10:38:49.017696581] [20081019-10:38:49.019394129] FileSystem /mnt/ffsb1 [20081019-10:38:49.021124628] ========== [20081019-10:38:49.022816250] num_dirs = 0 [20081019-10:38:49.024576125] starting files = 1024 [20081019-10:38:49.026272550] [20081019-10:38:49.028018990] min file size = 36700160 (35MB) [20081019-10:38:49.029690855] max file size = 36700160 (35MB) [20081019-10:38:49.031437797] directio = off [20081019-10:38:49.033103629] alignedio = on [20081019-10:38:49.034796627] bufferedio = off [20081019-10:38:49.036503955] [20081019-10:38:49.038266291] aging is off [20081019-10:38:49.039945623] current utilization = 52.33% [20081019-10:38:49.041729538] [20081019-10:38:49.043585468] checking existing fs: /mnt/ffsb1 [20081019-10:38:49.114324577] fs setup took 0 secs [20081019-10:38:49.439871274] Syncing()...0 sec [20081019-10:38:49.441779523] Starting Actual Benchmark At: Sun Oct 19 10:38:49 2008 [20081019-10:38:49.454750533] [20081019-10:44:10.408887597] Syncing()...14 sec [20081019-10:44:10.411848269] FFSB benchmark finished at: Sun Oct 19 10:44:10 2008 [20081019-10:44:10.414616741] [20081019-10:44:10.416614714] Results: [20081019-10:44:10.430635597] Benchmark took 320.97 sec [20081019-10:44:10.432906907] [20081019-10:44:10.435305952] Total Results [20081019-10:44:10.449850209] =============== [20081019-10:44:10.454005016] Throughput: 591.81 writes/sec -> 2.31MB/sec [20081019-10:44:10.456309912] 591.81 Transactions per Second [20081019-10:44:10.458684586] [20081019-10:44:10.460748514] System Call Latency statistics in millisecs [20081019-10:44:10.463090736] ===== [20081019-10:44:10.465568051] Min Avg Max Total Calls [20081019-10:44:10.467632743] ======== ======== ======== ============ [20081019-10:44:10.469887216] [ open] 0.005000 0.008693 0.028000 742 [20081019-10:44:10.472433245] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:44:10.476654962] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081019-10:44:10.478713147] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081019-10:44:10.481091120] msec_range[3] 500.000000 - 1000.000000 : 0 [20081019-10:44:10.483540936] msec_range[4] 200.000000 - 500.000000 : 0 [20081019-10:44:10.486013843] msec_range[5] 100.000000 - 200.000000 : 0 [20081019-10:44:10.488408596] msec_range[6] 50.000000 - 100.000000 : 0 [20081019-10:44:10.491654266] msec_range[7] 20.000000 - 50.000000 : 0 [20081019-10:44:10.494674939] msec_range[8] 10.000000 - 20.000000 : 0 [20081019-10:44:10.497010683] msec_range[9] 5.000000 - 10.000000 : 0 [20081019-10:44:10.499998272] msec_range[10] 2.000000 - 5.000000 : 0 [20081019-10:44:10.502492902] msec_range[11] 1.000000 - 2.000000 : 0 [20081019-10:44:10.504993707] msec_range[12] 0.500000 - 1.000000 : 0 [20081019-10:44:10.507069371] msec_range[13] 0.200000 - 0.500000 : 0 [20081019-10:44:10.509295514] msec_range[14] 0.100000 - 0.200000 : 0 [20081019-10:44:10.511768851] msec_range[15] 0.050000 - 0.100000 : 0 [20081019-10:44:10.514123927] msec_range[16] 0.020000 - 0.050000 : 29 [20081019-10:44:10.516365426] msec_range[17] 0.010000 - 0.020000 : 165 [20081019-10:44:10.519505032] msec_range[18] 0.000000 - 0.010000 : 548 [20081019-10:44:10.521924670] [20081019-10:44:10.524059065] [ write] 0.005000 1.610935 3043.135010 189952 [20081019-10:44:10.526214222] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:44:10.528591762] msec_range[1] 2000.000000 - 5000.000000 : 23 [20081019-10:44:10.530735004] msec_range[2] 1000.000000 - 2000.000000 : 73 [20081019-10:44:10.533022433] msec_range[3] 500.000000 - 1000.000000 : 100 [20081019-10:44:10.535277784] msec_range[4] 200.000000 - 500.000000 : 163 [20081019-10:44:10.537280891] msec_range[5] 100.000000 - 200.000000 : 43 [20081019-10:44:10.539231007] msec_range[6] 50.000000 - 100.000000 : 6 [20081019-10:44:10.541502572] msec_range[7] 20.000000 - 50.000000 : 21 [20081019-10:44:10.543690512] msec_range[8] 10.000000 - 20.000000 : 121 [20081019-10:44:10.545787877] msec_range[9] 5.000000 - 10.000000 : 400 [20081019-10:44:10.548604020] msec_range[10] 2.000000 - 5.000000 : 2766 [20081019-10:44:10.551020830] msec_range[11] 1.000000 - 2.000000 : 1027 [20081019-10:44:10.553420849] msec_range[12] 0.500000 - 1.000000 : 33 [20081019-10:44:10.555751281] msec_range[13] 0.200000 - 0.500000 : 8 [20081019-10:44:10.557924501] msec_range[14] 0.100000 - 0.200000 : 1 [20081019-10:44:10.560234991] msec_range[15] 0.050000 - 0.100000 : 43 [20081019-10:44:10.563503926] msec_range[16] 0.020000 - 0.050000 : 5232 [20081019-10:44:10.565990022] msec_range[17] 0.010000 - 0.020000 : 119300 [20081019-10:44:10.568209766] msec_range[18] 0.000000 - 0.010000 : 60592 [20081019-10:44:10.570614589] [20081019-10:44:10.573110154] [ lseek] 0.000000 0.000984 0.127000 189952 [20081019-10:44:10.575068105] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:44:10.577323981] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081019-10:44:10.579848909] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081019-10:44:10.582438841] msec_range[3] 500.000000 - 1000.000000 : 0 [20081019-10:44:10.584763601] msec_range[4] 200.000000 - 500.000000 : 0 [20081019-10:44:10.587161120] msec_range[5] 100.000000 - 200.000000 : 0 [20081019-10:44:10.589438278] msec_range[6] 50.000000 - 100.000000 : 0 [20081019-10:44:10.592484007] msec_range[7] 20.000000 - 50.000000 : 0 [20081019-10:44:10.595029657] msec_range[8] 10.000000 - 20.000000 : 0 [20081019-10:44:10.597405207] msec_range[9] 5.000000 - 10.000000 : 0 [20081019-10:44:10.600163704] msec_range[10] 2.000000 - 5.000000 : 0 [20081019-10:44:10.602782431] msec_range[11] 1.000000 - 2.000000 : 0 [20081019-10:44:10.605277805] msec_range[12] 0.500000 - 1.000000 : 0 [20081019-10:44:10.607795956] msec_range[13] 0.200000 - 0.500000 : 0 [20081019-10:44:10.610084318] msec_range[14] 0.100000 - 0.200000 : 2 [20081019-10:44:10.612347067] msec_range[15] 0.050000 - 0.100000 : 1 [20081019-10:44:10.615047699] msec_range[16] 0.020000 - 0.050000 : 9 [20081019-10:44:10.618176919] msec_range[17] 0.010000 - 0.020000 : 29 [20081019-10:44:10.620417552] msec_range[18] 0.000000 - 0.010000 : 189911 [20081019-10:44:10.622550471] [20081019-10:44:10.624576080] [ close] 0.001000 0.002535 0.009000 742 [20081019-10:44:10.626548081] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:44:10.628558031] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081019-10:44:10.630977742] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081019-10:44:10.633350542] msec_range[3] 500.000000 - 1000.000000 : 0 [20081019-10:44:10.635655357] msec_range[4] 200.000000 - 500.000000 : 0 [20081019-10:44:10.638061559] msec_range[5] 100.000000 - 200.000000 : 0 [20081019-10:44:10.640357826] msec_range[6] 50.000000 - 100.000000 : 0 [20081019-10:44:10.642441012] msec_range[7] 20.000000 - 50.000000 : 0 [20081019-10:44:10.644765957] msec_range[8] 10.000000 - 20.000000 : 0 [20081019-10:44:10.646980174] msec_range[9] 5.000000 - 10.000000 : 0 [20081019-10:44:10.649112374] msec_range[10] 2.000000 - 5.000000 : 0 [20081019-10:44:10.651198544] msec_range[11] 1.000000 - 2.000000 : 0 [20081019-10:44:10.653902701] msec_range[12] 0.500000 - 1.000000 : 0 [20081019-10:44:10.656301901] msec_range[13] 0.200000 - 0.500000 : 0 [20081019-10:44:10.659036036] msec_range[14] 0.100000 - 0.200000 : 0 [20081019-10:44:10.661629026] msec_range[15] 0.050000 - 0.100000 : 0 [20081019-10:44:10.664055473] msec_range[16] 0.020000 - 0.050000 : 0 [20081019-10:44:10.666572954] msec_range[17] 0.010000 - 0.020000 : 0 [20081019-10:44:10.668905171] msec_range[18] 0.000000 - 0.010000 : 742 [20081019-10:44:10.671333954] [20081019-10:44:10.673740876] [20081019-10:44:10.677023428] [20081019-10:44:10.679143349] [20081019-10:44:10.681284009] 0.1% User Time [20081019-10:44:10.683250783] 0.7% System Time [20081019-10:44:10.685405525] 0.9% CPU Utilization [20081019-10:44:10.687597931] Profilers reporting [20081019-10:44:10.982826125] Profilers postprocessing [20081019-10:44:12.169737267] Stopping profiling. [20081019-10:44:12.174639783] Killing daemon. [20081019-10:44:13.343983858] Processing File : /autobench/logs/ffsb.random_writes__threads_0001.08-10-19_10.38.40/analysis/oprofile.001 [20081019-10:44:13.346062830] Processing File : /autobench/logs/ffsb.random_writes__threads_0001.08-10-19_10.38.40/analysis/oprofile-brief.001 [20081019-10:44:13.459595332] Processing File : mpstat.001 [20081019-10:44:13.461832807] Discovered mpstat_interval=[5] [20081019-10:44:13.991428805] Processing Directory : sar.breakout.001 [20081019-10:44:13.993517576] Discovered sar_interval=[5] [20081019-10:44:14.111625460] Processing File : iostat.001 [20081019-10:44:14.113840890] Discovered iostat_interval=[5] [20081019-10:44:14.500028936] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-10-19_0957/ext3-baseline' [20081019-10:44:21.648313829] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081019-10:44:22.145733831] PROCESSING COMMAND : 'mount -t ext3 /dev/ffsbdev1 /mnt/ffsb1' [20081019-10:44:22.283000039] PROCESSING COMMAND : 'run random_writes__threads_0008 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb num_threads=8' [20081019-10:44:22.361222193] new log requested [20081019-10:44:22.393910427] Running command ffsb [20081019-10:44:29.475999272] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb [20081019-10:44:29.481299262] Importing argument : num_threads=8 [20081019-10:44:29.572191766] Checking for sar... [20081019-10:44:29.574521475] found [20081019-10:44:29.630024596] Checking for sar... [20081019-10:44:29.632257243] found [20081019-10:44:29.687380607] Checking for sar... [20081019-10:44:29.689519883] found [20081019-10:44:29.763153321] Checking for gettext... [20081019-10:44:29.766165678] found [20081019-10:44:29.768449597] Checking for libiberty... [20081019-10:44:29.770586142] found [20081019-10:44:29.772547170] Checking for popt... [20081019-10:44:29.774463115] found [20081019-10:44:29.776371930] Checking for popt64... [20081019-10:44:29.778224263] found [20081019-10:44:29.780219294] Checking for oprofile... [20081019-10:44:29.782117161] found [20081019-10:44:29.828672933] opcontrol: oprofile 0.9.3 compiled on Sep 18 2008 16:10:26 [20081019-10:44:29.906722126] Daemon not running [20081019-10:44:29.916821470] Unloading oprofile module [20081019-10:44:30.019891017] Daemon not running [20081019-10:44:30.321894325] Daemon not running [20081019-10:44:30.324018983] Separate options: none [20081019-10:44:30.326080396] vmlinux file: /boot/vmlinux-2.6.27-rc7 [20081019-10:44:30.328082066] Image filter: none [20081019-10:44:30.329998605] Call-graph depth: 0 [20081019-10:44:30.426904348] FFSB version 5.2.1 started [20081019-10:44:30.429128479] [20081019-10:44:30.456566989] benchmark time = 300 [20081019-10:44:30.458445858] ThreadGroup 0 [20081019-10:44:30.460512033] ================ [20081019-10:44:30.462491605] num_threads = 8 [20081019-10:44:30.464416348] [20081019-10:44:30.466269994] read_random = off [20081019-10:44:30.467989598] read_size = 0 (0B) [20081019-10:44:30.469761622] read_blocksize = 0 (0B) [20081019-10:44:30.471477607] read_skip = off [20081019-10:44:30.473217861] read_skipsize = 0 (0B) [20081019-10:44:30.474943965] [20081019-10:44:30.476690953] write_random = on [20081019-10:44:30.478371027] write_size = 1048576 (1MB) [20081019-10:44:30.480101106] fsync_file = 0 [20081019-10:44:30.481790710] write_blocksize = 4096 (4KB) [20081019-10:44:30.483596919] wait time = 0 [20081019-10:44:30.485259750] [20081019-10:44:30.486996019] op weights [20081019-10:44:30.488699484] read = 0 (0.00%) [20081019-10:44:30.490449788] readall = 0 (0.00%) [20081019-10:44:30.492100191] write = 1 (100.00%) [20081019-10:44:30.493879272] create = 0 (0.00%) [20081019-10:44:30.495744193] append = 0 (0.00%) [20081019-10:44:30.497477620] delete = 0 (0.00%) [20081019-10:44:30.499534971] metaop = 0 (0.00%) [20081019-10:44:30.501367530] createdir = 0 (0.00%) [20081019-10:44:30.503141592] stat = 0 (0.00%) [20081019-10:44:30.504844219] writeall = 0 (0.00%) [20081019-10:44:30.506751150] writeall_fsync = 0 (0.00%) [20081019-10:44:30.508463847] open_close = 0 (0.00%) [20081019-10:44:30.510208780] [20081019-10:44:30.511871320] FileSystem /mnt/ffsb1 [20081019-10:44:30.514055587] ========== [20081019-10:44:30.515926205] num_dirs = 0 [20081019-10:44:30.517694920] starting files = 1024 [20081019-10:44:30.519361919] [20081019-10:44:30.521150434] min file size = 36700160 (35MB) [20081019-10:44:30.522796556] max file size = 36700160 (35MB) [20081019-10:44:30.524551090] directio = off [20081019-10:44:30.526224535] alignedio = on [20081019-10:44:30.527964075] bufferedio = off [20081019-10:44:30.529655630] [20081019-10:44:30.531439588] aging is off [20081019-10:44:30.533095003] current utilization = 52.33% [20081019-10:44:30.534899375] [20081019-10:44:30.536633777] checking existing fs: /mnt/ffsb1 [20081019-10:44:30.612300618] fs setup took 0 secs [20081019-10:44:30.936780834] Syncing()...0 sec [20081019-10:44:30.938825116] Starting Actual Benchmark At: Sun Oct 19 10:44:30 2008 [20081019-10:44:30.951634917] [20081019-10:50:12.413009684] Syncing()...33 sec [20081019-10:50:12.415487885] FFSB benchmark finished at: Sun Oct 19 10:50:12 2008 [20081019-10:50:12.417956536] [20081019-10:50:12.420348691] Results: [20081019-10:50:12.434464917] Benchmark took 341.48 sec [20081019-10:50:12.436676960] [20081019-10:50:12.438901496] Total Results [20081019-10:50:12.453313947] =============== [20081019-10:50:12.456479993] Throughput: 570.51 writes/sec -> 2.23MB/sec [20081019-10:50:12.459001111] 570.51 Transactions per Second [20081019-10:50:12.461205232] [20081019-10:50:12.463408113] System Call Latency statistics in millisecs [20081019-10:50:12.465671180] ===== [20081019-10:50:12.468217227] Min Avg Max Total Calls [20081019-10:50:12.471027983] ======== ======== ======== ============ [20081019-10:50:12.473877491] [ open] 0.005000 0.011137 0.067000 761 [20081019-10:50:12.477548036] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:50:12.479881552] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081019-10:50:12.482297505] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081019-10:50:12.484451060] msec_range[3] 500.000000 - 1000.000000 : 0 [20081019-10:50:12.486612681] msec_range[4] 200.000000 - 500.000000 : 0 [20081019-10:50:12.489000775] msec_range[5] 100.000000 - 200.000000 : 0 [20081019-10:50:12.491286920] msec_range[6] 50.000000 - 100.000000 : 0 [20081019-10:50:12.493551012] msec_range[7] 20.000000 - 50.000000 : 0 [20081019-10:50:12.495896186] msec_range[8] 10.000000 - 20.000000 : 0 [20081019-10:50:12.498127499] msec_range[9] 5.000000 - 10.000000 : 0 [20081019-10:50:12.500441612] msec_range[10] 2.000000 - 5.000000 : 0 [20081019-10:50:12.503006296] msec_range[11] 1.000000 - 2.000000 : 0 [20081019-10:50:12.505143215] msec_range[12] 0.500000 - 1.000000 : 0 [20081019-10:50:12.508024033] msec_range[13] 0.200000 - 0.500000 : 0 [20081019-10:50:12.510533538] msec_range[14] 0.100000 - 0.200000 : 0 [20081019-10:50:12.512777930] msec_range[15] 0.050000 - 0.100000 : 1 [20081019-10:50:12.514946839] msec_range[16] 0.020000 - 0.050000 : 50 [20081019-10:50:12.517295068] msec_range[17] 0.010000 - 0.020000 : 350 [20081019-10:50:12.519638951] msec_range[18] 0.000000 - 0.010000 : 360 [20081019-10:50:12.522189092] [20081019-10:50:12.524534923] [ write] 0.005000 12.484842 18549.531250 194816 [20081019-10:50:12.526766029] msec_range[0] 5000.000000 - 10000.000000 : 2 [20081019-10:50:12.529201991] msec_range[1] 2000.000000 - 5000.000000 : 163 [20081019-10:50:12.531605873] msec_range[2] 1000.000000 - 2000.000000 : 477 [20081019-10:50:12.533684548] msec_range[3] 500.000000 - 1000.000000 : 865 [20081019-10:50:12.535886335] msec_range[4] 200.000000 - 500.000000 : 2069 [20081019-10:50:12.538156968] msec_range[5] 100.000000 - 200.000000 : 255 [20081019-10:50:12.540464399] msec_range[6] 50.000000 - 100.000000 : 87 [20081019-10:50:12.542505100] msec_range[7] 20.000000 - 50.000000 : 173 [20081019-10:50:12.544851971] msec_range[8] 10.000000 - 20.000000 : 199 [20081019-10:50:12.547369662] msec_range[9] 5.000000 - 10.000000 : 234 [20081019-10:50:12.549652805] msec_range[10] 2.000000 - 5.000000 : 332 [20081019-10:50:12.551667043] msec_range[11] 1.000000 - 2.000000 : 141 [20081019-10:50:12.554068257] msec_range[12] 0.500000 - 1.000000 : 4 [20081019-10:50:12.556856961] msec_range[13] 0.200000 - 0.500000 : 13 [20081019-10:50:12.559105709] msec_range[14] 0.100000 - 0.200000 : 14 [20081019-10:50:12.561451668] msec_range[15] 0.050000 - 0.100000 : 128 [20081019-10:50:12.563607577] msec_range[16] 0.020000 - 0.050000 : 13206 [20081019-10:50:12.565830844] msec_range[17] 0.010000 - 0.020000 : 97730 [20081019-10:50:12.568280534] msec_range[18] 0.000000 - 0.010000 : 78719 [20081019-10:50:12.570651026] [20081019-10:50:12.573024932] [ lseek] 0.000000 0.015738 1136.251953 194816 [20081019-10:50:12.575447957] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:50:12.577810235] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081019-10:50:12.580880593] msec_range[2] 1000.000000 - 2000.000000 : 1 [20081019-10:50:12.583450779] msec_range[3] 500.000000 - 1000.000000 : 0 [20081019-10:50:12.585834556] msec_range[4] 200.000000 - 500.000000 : 5 [20081019-10:50:12.587945326] msec_range[5] 100.000000 - 200.000000 : 1 [20081019-10:50:12.592134463] msec_range[6] 50.000000 - 100.000000 : 1 [20081019-10:50:12.595277431] msec_range[7] 20.000000 - 50.000000 : 2 [20081019-10:50:12.597706489] msec_range[8] 10.000000 - 20.000000 : 0 [20081019-10:50:12.599952575] msec_range[9] 5.000000 - 10.000000 : 0 [20081019-10:50:12.602535523] msec_range[10] 2.000000 - 5.000000 : 0 [20081019-10:50:12.604909873] msec_range[11] 1.000000 - 2.000000 : 0 [20081019-10:50:12.607122469] msec_range[12] 0.500000 - 1.000000 : 0 [20081019-10:50:12.609262778] msec_range[13] 0.200000 - 0.500000 : 2 [20081019-10:50:12.611514253] msec_range[14] 0.100000 - 0.200000 : 2 [20081019-10:50:12.613952769] msec_range[15] 0.050000 - 0.100000 : 6 [20081019-10:50:12.616424912] msec_range[16] 0.020000 - 0.050000 : 128 [20081019-10:50:12.618995088] msec_range[17] 0.010000 - 0.020000 : 550 [20081019-10:50:12.621837839] msec_range[18] 0.000000 - 0.010000 : 194118 [20081019-10:50:12.624214527] [20081019-10:50:12.626622075] [ close] 0.001000 0.003485 0.014000 761 [20081019-10:50:12.628869020] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:50:12.631039873] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081019-10:50:12.633134810] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081019-10:50:12.635413952] msec_range[3] 500.000000 - 1000.000000 : 0 [20081019-10:50:12.637562543] msec_range[4] 200.000000 - 500.000000 : 0 [20081019-10:50:12.639639258] msec_range[5] 100.000000 - 200.000000 : 0 [20081019-10:50:12.641702868] msec_range[6] 50.000000 - 100.000000 : 0 [20081019-10:50:12.644173671] msec_range[7] 20.000000 - 50.000000 : 0 [20081019-10:50:12.646866515] msec_range[8] 10.000000 - 20.000000 : 0 [20081019-10:50:12.649254996] msec_range[9] 5.000000 - 10.000000 : 0 [20081019-10:50:12.651686959] msec_range[10] 2.000000 - 5.000000 : 0 [20081019-10:50:12.654091596] msec_range[11] 1.000000 - 2.000000 : 0 [20081019-10:50:12.656344471] msec_range[12] 0.500000 - 1.000000 : 0 [20081019-10:50:12.658773472] msec_range[13] 0.200000 - 0.500000 : 0 [20081019-10:50:12.662564720] msec_range[14] 0.100000 - 0.200000 : 0 [20081019-10:50:12.664986481] msec_range[15] 0.050000 - 0.100000 : 0 [20081019-10:50:12.667285877] msec_range[16] 0.020000 - 0.050000 : 0 [20081019-10:50:12.669529150] msec_range[17] 0.010000 - 0.020000 : 9 [20081019-10:50:12.672026818] msec_range[18] 0.000000 - 0.010000 : 752 [20081019-10:50:12.674304702] [20081019-10:50:12.676694445] [20081019-10:50:12.679032068] [20081019-10:50:12.681371924] [20081019-10:50:12.684338894] 0.1% User Time [20081019-10:50:12.686526797] 0.8% System Time [20081019-10:50:12.688529117] 0.9% CPU Utilization [20081019-10:50:12.690877789] Profilers reporting [20081019-10:50:12.973914836] Profilers postprocessing [20081019-10:50:14.160642477] Stopping profiling. [20081019-10:50:14.165256171] Killing daemon. [20081019-10:50:14.309127661] Processing File : /autobench/logs/ffsb.random_writes__threads_0008.08-10-19_10.44.22/analysis/oprofile.001 [20081019-10:50:14.311242007] Processing File : /autobench/logs/ffsb.random_writes__threads_0008.08-10-19_10.44.22/analysis/oprofile-brief.001 [20081019-10:50:14.428925616] Processing File : mpstat.001 [20081019-10:50:14.431057987] Discovered mpstat_interval=[5] [20081019-10:50:14.977881553] Processing Directory : sar.breakout.001 [20081019-10:50:14.980070753] Discovered sar_interval=[5] [20081019-10:50:15.101238774] Processing File : iostat.001 [20081019-10:50:15.103203465] Discovered iostat_interval=[5] [20081019-10:50:15.484701030] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-10-19_0957/ext3-baseline' [20081019-10:50:22.689397120] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081019-10:50:23.187399561] PROCESSING COMMAND : 'mount -t ext3 /dev/ffsbdev1 /mnt/ffsb1' [20081019-10:50:23.318574306] PROCESSING COMMAND : 'run random_writes__threads_0032 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb num_threads=32' [20081019-10:50:23.390909388] new log requested [20081019-10:50:23.412912248] Running command ffsb [20081019-10:50:30.513364421] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/random_writes.ffsb [20081019-10:50:30.518593621] Importing argument : num_threads=32 [20081019-10:50:30.609369837] Checking for sar... [20081019-10:50:30.611466146] found [20081019-10:50:30.666626651] Checking for sar... [20081019-10:50:30.668718707] found [20081019-10:50:30.724435419] Checking for sar... [20081019-10:50:30.726538101] found [20081019-10:50:30.800084682] Checking for gettext... [20081019-10:50:30.803078721] found [20081019-10:50:30.805366673] Checking for libiberty... [20081019-10:50:30.807329249] found [20081019-10:50:30.809348112] Checking for popt... [20081019-10:50:30.811304577] found [20081019-10:50:30.812999635] Checking for popt64... [20081019-10:50:30.814821376] found [20081019-10:50:30.816559754] Checking for oprofile... [20081019-10:50:30.818179081] found [20081019-10:50:30.864884835] opcontrol: oprofile 0.9.3 compiled on Sep 18 2008 16:10:26 [20081019-10:50:30.942540187] Daemon not running [20081019-10:50:30.952781388] Unloading oprofile module [20081019-10:50:31.056260376] Daemon not running [20081019-10:50:31.347738271] Daemon not running [20081019-10:50:31.349732416] Separate options: none [20081019-10:50:31.351769962] vmlinux file: /boot/vmlinux-2.6.27-rc7 [20081019-10:50:31.353729367] Image filter: none [20081019-10:50:31.355619943] Call-graph depth: 0 [20081019-10:50:31.453198759] FFSB version 5.2.1 started [20081019-10:50:31.455392233] [20081019-10:50:31.574705864] benchmark time = 300 [20081019-10:50:31.576801547] ThreadGroup 0 [20081019-10:50:31.578772782] ================ [20081019-10:50:31.580807092] num_threads = 32 [20081019-10:50:31.583024576] [20081019-10:50:31.584863985] read_random = off [20081019-10:50:31.586662355] read_size = 0 (0B) [20081019-10:50:31.588389702] read_blocksize = 0 (0B) [20081019-10:50:31.590163959] read_skip = off [20081019-10:50:31.591862112] read_skipsize = 0 (0B) [20081019-10:50:31.593652442] [20081019-10:50:31.595348162] write_random = on [20081019-10:50:31.597109541] write_size = 1048576 (1MB) [20081019-10:50:31.598818060] fsync_file = 0 [20081019-10:50:31.600586888] write_blocksize = 4096 (4KB) [20081019-10:50:31.602269977] wait time = 0 [20081019-10:50:31.604013940] [20081019-10:50:31.605690270] op weights [20081019-10:50:31.607463775] read = 0 (0.00%) [20081019-10:50:31.609175442] readall = 0 (0.00%) [20081019-10:50:31.610902800] write = 1 (100.00%) [20081019-10:50:31.612561119] create = 0 (0.00%) [20081019-10:50:31.614348006] append = 0 (0.00%) [20081019-10:50:31.616077169] delete = 0 (0.00%) [20081019-10:50:31.618116362] metaop = 0 (0.00%) [20081019-10:50:31.620033218] createdir = 0 (0.00%) [20081019-10:50:31.621920900] stat = 0 (0.00%) [20081019-10:50:31.623624489] writeall = 0 (0.00%) [20081019-10:50:31.625393305] writeall_fsync = 0 (0.00%) [20081019-10:50:31.627086311] open_close = 0 (0.00%) [20081019-10:50:31.628878854] [20081019-10:50:31.630588734] FileSystem /mnt/ffsb1 [20081019-10:50:31.632356609] ========== [20081019-10:50:31.634039301] num_dirs = 0 [20081019-10:50:31.635804137] starting files = 1024 [20081019-10:50:31.637494391] [20081019-10:50:31.639248660] min file size = 36700160 (35MB) [20081019-10:50:31.640921855] max file size = 36700160 (35MB) [20081019-10:50:31.642796032] directio = off [20081019-10:50:31.644469149] alignedio = on [20081019-10:50:31.646216196] bufferedio = off [20081019-10:50:31.647896593] [20081019-10:50:31.649648890] aging is off [20081019-10:50:31.651350277] current utilization = 52.33% [20081019-10:50:31.653119531] [20081019-10:50:31.654801549] checking existing fs: /mnt/ffsb1 [20081019-10:50:31.716811540] fs setup took 0 secs [20081019-10:50:32.026025501] Syncing()...0 sec [20081019-10:50:32.028772169] Starting Actual Benchmark At: Sun Oct 19 10:50:32 2008 [20081019-10:50:32.041813289] [20081019-10:56:28.634245027] Syncing()...39 sec [20081019-10:56:28.636897561] FFSB benchmark finished at: Sun Oct 19 10:56:28 2008 [20081019-10:56:28.639397220] [20081019-10:56:28.641798948] Results: [20081019-10:56:28.656278802] Benchmark took 356.61 sec [20081019-10:56:28.658392468] [20081019-10:56:28.660565428] Total Results [20081019-10:56:28.674579962] =============== [20081019-10:56:28.676994269] Throughput: 552.76 writes/sec -> 2.16MB/sec [20081019-10:56:28.680836196] 552.76 Transactions per Second [20081019-10:56:28.683450720] [20081019-10:56:28.685803143] System Call Latency statistics in millisecs [20081019-10:56:28.687978451] ===== [20081019-10:56:28.690458915] Min Avg Max Total Calls [20081019-10:56:28.692681803] ======== ======== ======== ============ [20081019-10:56:28.695385755] [ open] 0.006000 0.010827 0.041000 770 [20081019-10:56:28.697747013] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:56:28.700216032] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081019-10:56:28.702741266] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081019-10:56:28.705003229] msec_range[3] 500.000000 - 1000.000000 : 0 [20081019-10:56:28.707466576] msec_range[4] 200.000000 - 500.000000 : 0 [20081019-10:56:28.709985258] msec_range[5] 100.000000 - 200.000000 : 0 [20081019-10:56:28.712614258] msec_range[6] 50.000000 - 100.000000 : 0 [20081019-10:56:28.714952084] msec_range[7] 20.000000 - 50.000000 : 0 [20081019-10:56:28.717254397] msec_range[8] 10.000000 - 20.000000 : 0 [20081019-10:56:28.719546092] msec_range[9] 5.000000 - 10.000000 : 0 [20081019-10:56:28.721799068] msec_range[10] 2.000000 - 5.000000 : 0 [20081019-10:56:28.724963385] msec_range[11] 1.000000 - 2.000000 : 0 [20081019-10:56:28.727520913] msec_range[12] 0.500000 - 1.000000 : 0 [20081019-10:56:28.730317085] msec_range[13] 0.200000 - 0.500000 : 0 [20081019-10:56:28.733398225] msec_range[14] 0.100000 - 0.200000 : 0 [20081019-10:56:28.735959909] msec_range[15] 0.050000 - 0.100000 : 0 [20081019-10:56:28.738308630] msec_range[16] 0.020000 - 0.050000 : 55 [20081019-10:56:28.740677499] msec_range[17] 0.010000 - 0.020000 : 318 [20081019-10:56:28.743171936] msec_range[18] 0.000000 - 0.010000 : 397 [20081019-10:56:28.745440219] [20081019-10:56:28.747564869] [ write] 0.005000 48.957971 109941.703125 197120 [20081019-10:56:28.749867806] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:56:28.752117754] msec_range[1] 2000.000000 - 5000.000000 : 23 [20081019-10:56:28.754310028] msec_range[2] 1000.000000 - 2000.000000 : 135 [20081019-10:56:28.756741265] msec_range[3] 500.000000 - 1000.000000 : 692 [20081019-10:56:28.759025217] msec_range[4] 200.000000 - 500.000000 : 2802 [20081019-10:56:28.761415563] msec_range[5] 100.000000 - 200.000000 : 187 [20081019-10:56:28.763558837] msec_range[6] 50.000000 - 100.000000 : 171 [20081019-10:56:28.765786811] msec_range[7] 20.000000 - 50.000000 : 279 [20081019-10:56:28.767928948] msec_range[8] 10.000000 - 20.000000 : 260 [20081019-10:56:28.770295155] msec_range[9] 5.000000 - 10.000000 : 188 [20081019-10:56:28.772897116] msec_range[10] 2.000000 - 5.000000 : 215 [20081019-10:56:28.775329821] msec_range[11] 1.000000 - 2.000000 : 62 [20081019-10:56:28.777342424] msec_range[12] 0.500000 - 1.000000 : 7 [20081019-10:56:28.779643406] msec_range[13] 0.200000 - 0.500000 : 18 [20081019-10:56:28.782084753] msec_range[14] 0.100000 - 0.200000 : 26 [20081019-10:56:28.784391616] msec_range[15] 0.050000 - 0.100000 : 253 [20081019-10:56:28.786865137] msec_range[16] 0.020000 - 0.050000 : 16395 [20081019-10:56:28.789351461] msec_range[17] 0.010000 - 0.020000 : 105701 [20081019-10:56:28.791684595] msec_range[18] 0.000000 - 0.010000 : 69559 [20081019-10:56:28.794314338] [20081019-10:56:28.796699900] [ lseek] 0.000000 1.490354 58637.640625 197120 [20081019-10:56:28.798940657] msec_range[0] 5000.000000 - 10000.000000 : 2 [20081019-10:56:28.801150270] msec_range[1] 2000.000000 - 5000.000000 : 1 [20081019-10:56:28.803816485] msec_range[2] 1000.000000 - 2000.000000 : 2 [20081019-10:56:28.806415173] msec_range[3] 500.000000 - 1000.000000 : 9 [20081019-10:56:28.808784630] msec_range[4] 200.000000 - 500.000000 : 25 [20081019-10:56:28.812676859] msec_range[5] 100.000000 - 200.000000 : 7 [20081019-10:56:28.815210242] msec_range[6] 50.000000 - 100.000000 : 1 [20081019-10:56:28.817614009] msec_range[7] 20.000000 - 50.000000 : 4 [20081019-10:56:28.820194036] msec_range[8] 10.000000 - 20.000000 : 2 [20081019-10:56:28.822816235] msec_range[9] 5.000000 - 10.000000 : 2 [20081019-10:56:28.825837189] msec_range[10] 2.000000 - 5.000000 : 5 [20081019-10:56:28.828072869] msec_range[11] 1.000000 - 2.000000 : 3 [20081019-10:56:28.830459212] msec_range[12] 0.500000 - 1.000000 : 2 [20081019-10:56:28.832854970] msec_range[13] 0.200000 - 0.500000 : 6 [20081019-10:56:28.835304288] msec_range[14] 0.100000 - 0.200000 : 11 [20081019-10:56:28.837636939] msec_range[15] 0.050000 - 0.100000 : 18 [20081019-10:56:28.840044072] msec_range[16] 0.020000 - 0.050000 : 1174 [20081019-10:56:28.842207600] msec_range[17] 0.010000 - 0.020000 : 3416 [20081019-10:56:28.844480848] msec_range[18] 0.000000 - 0.010000 : 192424 [20081019-10:56:28.846610509] [20081019-10:56:28.848798095] [ close] 0.001000 0.003568 0.044000 770 [20081019-10:56:28.850952485] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-10:56:28.853106989] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081019-10:56:28.855298044] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081019-10:56:28.857550833] msec_range[3] 500.000000 - 1000.000000 : 0 [20081019-10:56:28.859693606] msec_range[4] 200.000000 - 500.000000 : 0 [20081019-10:56:28.861989419] msec_range[5] 100.000000 - 200.000000 : 0 [20081019-10:56:28.864253471] msec_range[6] 50.000000 - 100.000000 : 0 [20081019-10:56:28.866379046] msec_range[7] 20.000000 - 50.000000 : 0 [20081019-10:56:28.868711440] msec_range[8] 10.000000 - 20.000000 : 0 [20081019-10:56:28.870952605] msec_range[9] 5.000000 - 10.000000 : 0 [20081019-10:56:28.872946172] msec_range[10] 2.000000 - 5.000000 : 0 [20081019-10:56:28.875172980] msec_range[11] 1.000000 - 2.000000 : 0 [20081019-10:56:28.877505021] msec_range[12] 0.500000 - 1.000000 : 0 [20081019-10:56:28.880179216] msec_range[13] 0.200000 - 0.500000 : 0 [20081019-10:56:28.882365698] msec_range[14] 0.100000 - 0.200000 : 0 [20081019-10:56:28.885109296] msec_range[15] 0.050000 - 0.100000 : 0 [20081019-10:56:28.887358163] msec_range[16] 0.020000 - 0.050000 : 1 [20081019-10:56:28.889877679] msec_range[17] 0.010000 - 0.020000 : 12 [20081019-10:56:28.892205369] msec_range[18] 0.000000 - 0.010000 : 757 [20081019-10:56:28.894435047] [20081019-10:56:28.896758619] [20081019-10:56:28.899061636] [20081019-10:56:28.901247442] [20081019-10:56:28.905960137] 0.1% User Time [20081019-10:56:28.907949181] 1.2% System Time [20081019-10:56:28.910182178] 1.3% CPU Utilization [20081019-10:56:28.912523036] Profilers reporting [20081019-10:56:29.202341265] Profilers postprocessing [20081019-10:56:30.390241310] Stopping profiling. [20081019-10:56:30.394969950] Killing daemon. [20081019-10:56:31.563069125] Processing File : /autobench/logs/ffsb.random_writes__threads_0032.08-10-19_10.50.23/analysis/oprofile.001 [20081019-10:56:31.565152353] Processing File : /autobench/logs/ffsb.random_writes__threads_0032.08-10-19_10.50.23/analysis/oprofile-brief.001 [20081019-10:56:31.685111026] Processing File : mpstat.001 [20081019-10:56:31.687195813] Discovered mpstat_interval=[5] [20081019-10:56:32.244850833] Processing Directory : sar.breakout.001 [20081019-10:56:32.247104396] Discovered sar_interval=[5] [20081019-10:56:32.369396379] Processing File : iostat.001 [20081019-10:56:32.371679606] Discovered iostat_interval=[5] [20081019-10:56:32.757309155] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-10-19_0957/ext3-baseline' [20081019-10:56:39.499257556] PROCESSING COMMAND : 'umount /mnt/ffsb1' [20081019-10:56:40.094159151] PROCESSING COMMAND : 'mkfs.ext3 -F /dev/ffsbdev1' [20081019-10:56:40.225356700] mke2fs 1.41.2 (02-Oct-2008) [20081019-10:56:40.238239589] Filesystem label= [20081019-10:56:40.240336715] OS type: Linux [20081019-10:56:40.242268991] Block size=4096 (log=2) [20081019-10:56:40.244276027] Fragment size=4096 (log=2) [20081019-10:56:40.246245309] 4481024 inodes, 17921750 blocks [20081019-10:56:40.248024856] 896087 blocks (5.00%) reserved for the super user [20081019-10:56:40.249929092] First data block=0 [20081019-10:56:40.251818060] Maximum filesystem blocks=4294967296 [20081019-10:56:40.253626734] 547 block groups [20081019-10:56:40.255744306] 32768 blocks per group, 32768 fragments per group [20081019-10:56:40.257669968] 8192 inodes per group [20081019-10:56:40.259462717] Superblock backups stored on blocks: [20081019-10:56:40.261204177] 32768, 98304, 163840, 229376, 294912, 819200, 884736, 1605632, 2654208, [20081019-10:56:40.263141525] 4096000, 7962624, 11239424 [20081019-10:56:40.265016143] [20081019-10:56:52.086232331] 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 [20081019-10:56:53.975378520] Creating journal (32768 blocks): done [20081019-10:56:57.729210198] Writing superblocks and filesystem accounting information: done [20081019-10:56:58.150587607] [20081019-10:56:58.152755370] This filesystem will be automatically checked every 35 mounts or [20081019-10:56:58.157119956] 180 days, whichever comes first. Use tune2fs -c or -i to override. [20081019-10:56:58.204447729] PROCESSING COMMAND : 'mount -t ext3 /dev/ffsbdev1 /mnt/ffsb1' [20081019-10:56:58.324588958] PROCESSING COMMAND : 'run large_file_creates__threads_0001 ffsb /hks/users/corry/btrfs/ffsb/profiles/btrfs2/large_file_creates.ffsb num_threads=1' [20081019-10:56:58.367596795] new log requested [20081019-10:56:58.389796903] Running command ffsb [20081019-10:57:05.540406464] Using profile /hks/users/corry/btrfs/ffsb/profiles/btrfs2/large_file_creates.ffsb [20081019-10:57:05.553091848] Importing argument : num_threads=1 [20081019-10:57:05.643131349] Checking for sar... [20081019-10:57:05.645214974] found [20081019-10:57:05.700813585] Checking for sar... [20081019-10:57:05.702988984] found [20081019-10:57:05.758688596] Checking for sar... [20081019-10:57:05.760946309] found [20081019-10:57:05.834662730] Checking for gettext... [20081019-10:57:05.836891477] found [20081019-10:57:05.839131474] Checking for libiberty... [20081019-10:57:05.841350853] found [20081019-10:57:05.843199440] Checking for popt... [20081019-10:57:05.845256228] found [20081019-10:57:05.847195553] Checking for popt64... [20081019-10:57:05.849119065] found [20081019-10:57:05.851037073] Checking for oprofile... [20081019-10:57:05.852911982] found [20081019-10:57:05.899780664] opcontrol: oprofile 0.9.3 compiled on Sep 18 2008 16:10:26 [20081019-10:57:05.977392902] Daemon not running [20081019-10:57:05.987450685] Unloading oprofile module [20081019-10:57:06.086396341] Daemon not running [20081019-10:57:06.376535587] Daemon not running [20081019-10:57:06.378526810] Separate options: none [20081019-10:57:06.380631555] vmlinux file: /boot/vmlinux-2.6.27-rc7 [20081019-10:57:06.382571737] Image filter: none [20081019-10:57:06.384624574] Call-graph depth: 0 [20081019-10:57:06.481433185] FFSB version 5.2.1 started [20081019-10:57:06.483703097] [20081019-10:57:06.485518934] benchmark time = 300 [20081019-10:57:06.487468577] ThreadGroup 0 [20081019-10:57:06.489579158] ================ [20081019-10:57:06.491718888] num_threads = 1 [20081019-10:57:06.493678219] [20081019-10:57:06.495719001] read_random = off [20081019-10:57:06.497559403] read_size = 0 (0B) [20081019-10:57:06.499372176] read_blocksize = 0 (0B) [20081019-10:57:06.501138756] read_skip = off [20081019-10:57:06.502933013] read_skipsize = 0 (0B) [20081019-10:57:06.504631121] [20081019-10:57:06.506506577] write_random = off [20081019-10:57:06.508217390] write_size = 0 (0B) [20081019-10:57:06.510178657] fsync_file = 0 [20081019-10:57:06.512197621] write_blocksize = 4096 (4KB) [20081019-10:57:06.599716606] wait time = 0 [20081019-10:57:06.601709463] [20081019-10:57:06.603493386] op weights [20081019-10:57:06.605291735] read = 0 (0.00%) [20081019-10:57:06.607004445] readall = 0 (0.00%) [20081019-10:57:06.608819606] write = 0 (0.00%) [20081019-10:57:06.610651026] create = 1 (100.00%) [20081019-10:57:06.612574673] append = 0 (0.00%) [20081019-10:57:06.614477167] delete = 0 (0.00%) [20081019-10:57:06.616340798] metaop = 0 (0.00%) [20081019-10:57:06.618044058] createdir = 0 (0.00%) [20081019-10:57:06.619826763] stat = 0 (0.00%) [20081019-10:57:06.621528229] writeall = 0 (0.00%) [20081019-10:57:06.623250549] writeall_fsync = 0 (0.00%) [20081019-10:57:06.624967007] open_close = 0 (0.00%) [20081019-10:57:06.626738700] [20081019-10:57:06.628412766] FileSystem /mnt/ffsb1 [20081019-10:57:06.630195865] ========== [20081019-10:57:06.631874589] num_dirs = 0 [20081019-10:57:06.633630620] starting files = 0 [20081019-10:57:06.635321642] [20081019-10:57:06.637152314] min file size = 104857600 (100MB) [20081019-10:57:06.647574888] max file size = 104857600 (100MB) [20081019-10:57:06.649323566] directio = off [20081019-10:57:06.651130997] alignedio = on [20081019-10:57:06.653085149] bufferedio = off [20081019-10:57:06.654797634] [20081019-10:57:06.656584193] aging is off [20081019-10:57:06.658306500] current utilization = 0.26% [20081019-10:57:06.660209873] [20081019-10:57:06.661947184] creating new fileset /mnt/ffsb1 [20081019-10:57:06.663722247] fs setup took 0 secs [20081019-10:57:06.879095628] Syncing()...0 sec [20081019-10:57:06.881047191] Starting Actual Benchmark At: Sun Oct 19 10:57:06 2008 [20081019-10:57:06.893516883] [20081019-11:02:12.777590132] Syncing()...3 sec [20081019-11:02:12.819123300] FFSB benchmark finished at: Sun Oct 19 11:02:12 2008 [20081019-11:02:12.821672500] [20081019-11:02:12.824070380] Results: [20081019-11:02:12.865415999] Benchmark took 305.76 sec [20081019-11:02:12.867525050] [20081019-11:02:12.869413299] Total Results [20081019-11:02:12.883719297] =============== [20081019-11:02:12.886079463] Throughput: 20931.20 creates/sec -> 81.8MB/sec [20081019-11:02:12.888461406] 20931.20 Transactions per Second [20081019-11:02:12.890683904] [20081019-11:02:12.892589815] System Call Latency statistics in millisecs [20081019-11:02:12.894765709] ===== [20081019-11:02:12.896850416] Min Avg Max Total Calls [20081019-11:02:12.899044635] ======== ======== ======== ============ [20081019-11:02:12.901420748] [ open] 0.046000 3.221136 717.093018 250 [20081019-11:02:12.903606804] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-11:02:12.905647065] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081019-11:02:12.907631648] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081019-11:02:12.909636149] msec_range[3] 500.000000 - 1000.000000 : 1 [20081019-11:02:12.911555260] msec_range[4] 200.000000 - 500.000000 : 0 [20081019-11:02:12.913677628] msec_range[5] 100.000000 - 200.000000 : 0 [20081019-11:02:12.915704315] msec_range[6] 50.000000 - 100.000000 : 0 [20081019-11:02:12.917941476] msec_range[7] 20.000000 - 50.000000 : 2 [20081019-11:02:12.920084986] msec_range[8] 10.000000 - 20.000000 : 0 [20081019-11:02:12.921964703] msec_range[9] 5.000000 - 10.000000 : 0 [20081019-11:02:12.924167121] msec_range[10] 2.000000 - 5.000000 : 0 [20081019-11:02:12.926445245] msec_range[11] 1.000000 - 2.000000 : 0 [20081019-11:02:12.928555007] msec_range[12] 0.500000 - 1.000000 : 0 [20081019-11:02:12.930913881] msec_range[13] 0.200000 - 0.500000 : 3 [20081019-11:02:12.933016115] msec_range[14] 0.100000 - 0.200000 : 16 [20081019-11:02:12.935209408] msec_range[15] 0.050000 - 0.100000 : 225 [20081019-11:02:12.937234263] msec_range[16] 0.020000 - 0.050000 : 3 [20081019-11:02:12.939280305] msec_range[17] 0.010000 - 0.020000 : 0 [20081019-11:02:12.941254748] msec_range[18] 0.000000 - 0.010000 : 0 [20081019-11:02:12.943247837] [20081019-11:02:12.945386438] [ write] 0.014000 0.046349 2608.665039 6400000 [20081019-11:02:12.948249077] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-11:02:12.951694532] msec_range[1] 2000.000000 - 5000.000000 : 1 [20081019-11:02:12.953755367] msec_range[2] 1000.000000 - 2000.000000 : 12 [20081019-11:02:12.956038061] msec_range[3] 500.000000 - 1000.000000 : 115 [20081019-11:02:12.958259642] msec_range[4] 200.000000 - 500.000000 : 114 [20081019-11:02:12.960362461] msec_range[5] 100.000000 - 200.000000 : 47 [20081019-11:02:12.962236221] msec_range[6] 50.000000 - 100.000000 : 53 [20081019-11:02:12.964298012] msec_range[7] 20.000000 - 50.000000 : 91 [20081019-11:02:12.966287231] msec_range[8] 10.000000 - 20.000000 : 46 [20081019-11:02:12.968331795] msec_range[9] 5.000000 - 10.000000 : 352 [20081019-11:02:12.970219407] msec_range[10] 2.000000 - 5.000000 : 120 [20081019-11:02:12.984899476] msec_range[11] 1.000000 - 2.000000 : 71 [20081019-11:02:12.987170014] msec_range[12] 0.500000 - 1.000000 : 336 [20081019-11:02:12.989218471] msec_range[13] 0.200000 - 0.500000 : 22647 [20081019-11:02:12.991592708] msec_range[14] 0.100000 - 0.200000 : 5797 [20081019-11:02:12.993870311] msec_range[15] 0.050000 - 0.100000 : 36859 [20081019-11:02:12.995833612] msec_range[16] 0.020000 - 0.050000 : 2845871 [20081019-11:02:12.997789196] msec_range[17] 0.010000 - 0.020000 : 3487468 [20081019-11:02:12.999816364] msec_range[18] 0.000000 - 0.010000 : 0 [20081019-11:02:13.001761116] [20081019-11:02:13.003774105] [ close] 0.006000 0.008724 0.076000 250 [20081019-11:02:13.005671763] msec_range[0] 5000.000000 - 10000.000000 : 0 [20081019-11:02:13.007836804] msec_range[1] 2000.000000 - 5000.000000 : 0 [20081019-11:02:13.009746466] msec_range[2] 1000.000000 - 2000.000000 : 0 [20081019-11:02:13.011685876] msec_range[3] 500.000000 - 1000.000000 : 0 [20081019-11:02:13.013565833] msec_range[4] 200.000000 - 500.000000 : 0 [20081019-11:02:13.015545301] msec_range[5] 100.000000 - 200.000000 : 0 [20081019-11:02:13.017426169] msec_range[6] 50.000000 - 100.000000 : 0 [20081019-11:02:13.019495902] msec_range[7] 20.000000 - 50.000000 : 0 [20081019-11:02:13.021409907] msec_range[8] 10.000000 - 20.000000 : 0 [20081019-11:02:13.023509870] msec_range[9] 5.000000 - 10.000000 : 0 [20081019-11:02:13.025492306] msec_range[10] 2.000000 - 5.000000 : 0 [20081019-11:02:13.027494486] msec_range[11] 1.000000 - 2.000000 : 0 [20081019-11:02:13.029380853] msec_range[12] 0.500000 - 1.000000 : 0 [20081019-11:02:13.031336429] msec_range[13] 0.200000 - 0.500000 : 0 [20081019-11:02:13.033263656] msec_range[14] 0.100000 - 0.200000 : 0 [20081019-11:02:13.035199197] msec_range[15] 0.050000 - 0.100000 : 1 [20081019-11:02:13.037044432] msec_range[16] 0.020000 - 0.050000 : 1 [20081019-11:02:13.038996813] msec_range[17] 0.010000 - 0.020000 : 54 [20081019-11:02:13.040886947] msec_range[18] 0.000000 - 0.010000 : 194 [20081019-11:02:13.042809095] [20081019-11:02:13.044641581] [20081019-11:02:13.046535752] [20081019-11:02:13.048391175] [20081019-11:02:13.050339445] 2.7% User Time [20081019-11:02:13.052204201] 47.0% System Time [20081019-11:02:13.054115497] 49.8% CPU Utilization [20081019-11:02:13.056003249] Profilers reporting [20081019-11:02:16.268636237] Profilers postprocessing [20081019-11:02:17.477459663] Stopping profiling. [20081019-11:02:17.482248327] Killing daemon. [20081019-11:02:17.962333522] Processing File : /autobench/logs/ffsb.large_file_creates__threads_0001.08-10-19_10.56.58/analysis/oprofile.001 [20081019-11:02:17.964647477] Processing File : /autobench/logs/ffsb.large_file_creates__threads_0001.08-10-19_10.56.58/analysis/oprofile-brief.001 [20081019-11:02:18.166786658] Processing File : mpstat.001 [20081019-11:02:18.168789570] Discovered mpstat_interval=[5] [20081019-11:02:18.735381781] Processing Directory : sar.breakout.001 [20081019-11:02:18.737581809] Discovered sar_interval=[5] [20081019-11:02:18.870611660] Processing File : iostat.001 [20081019-11:02:18.872797477] Discovered iostat_interval=[5] [20081019-11:02:20.246957745] PROCESSING COMMAND : 'results hks.austin.ibm.com/benchmarks/results/btrfs/ffsb/btrfs2/2008-10-19_0957/ext3-baseline'