# IO bugfixes and improvements; more support for cache/seek measurements

adts: slight improvements
allocators: change POOL_VARIABLE_ALLOCS to -1 for safety; fix invalid
assumptions of it being 0
lib: more expressive param names
file: add file_get_random_name for randomized trace generation; allow
file_cache.h to declare externally visible file_buf_alloc API

file_cache: zero-length file bugfix; also add several flags to the API
routines allowing statistics gathering to be disabled (avoids distorting
stats due to e.g. trace_entry_causes_io cache simulation)

file_stats: add archive builder info; separate IO timing and seek
accounting (-> correct results)

trace: add random generation capability
vfs: made responsible for cache hit/miss accounting (fixes cache miss
rate display)

This was SVN commit r3681.

source/lib/adts.cpp

@@ -96,7 +96,7 @@ static void test_cache_removal()
 	Cache<int, int, Landlord_Lazy> c3;
 	Cache<int, int, Landlord_Lazy, Divider_Recip> c3r;
 
-#if 0
+#if defined(ENABLE_CACHE_POLICY_BENCHMARK) || 0
 	// set max priority, to reduce interference while measuring.
 	int old_policy; static sched_param old_param;	// (static => 0-init)
 	pthread_getschedparam(pthread_self(), &old_policy, &old_param);

source/lib/adts.h

@@ -468,7 +468,7 @@ again:
 		{
 			Entry& entry = it->second;
 
-			entry.credit -= min_credit_density * entry.size;
+			charge(entry, min_credit_density);
 			if(should_evict(entry))
 			{
 				entry_list.push_back(entry);
@@ -523,6 +523,14 @@ protected:
 		map.erase(it);
 	}
 
+	void charge(Entry& entry, float delta)
+	{
+		entry.credit -= delta * entry.size;
+
+		// don't worry about entry.size being 0 - if so, cost
+		// should also be 0, so credit will already be 0 anyway.
+	}
+
 	// for each entry, 'charge' it (i.e. reduce credit by) delta * its size.
 	// delta is typically MCD (see above); however, several such updates
 	// may be lumped together to save time. Landlord_Lazy does this.
@@ -721,7 +729,7 @@ template
 typename Key, typename Item,
 // see documentation above for Manager's interface.
 template<typename Key, class Entry> class Manager = Landlord_Cached,
-class Divider = Divider_Recip
+class Divider = Divider_Naive
 >
 class Cache
 {

source/lib/allocators.cpp

@@ -411,7 +411,10 @@ static const size_t ALIGN = 8;
 // returned by pool_alloc (whose size parameter is then ignored).
 LibError pool_create(Pool* p, size_t max_size, size_t el_size)
 {
-	p->el_size = round_up(el_size, ALIGN);
+	if(el_size == POOL_VARIABLE_ALLOCS)
+		p->el_size = 0;
+	else
+		p->el_size = round_up(el_size, ALIGN);
 	p->freelist = 0;
 	RETURN_ERR(da_alloc(&p->da, max_size));
 	return ERR_OK;

source/lib/allocators.h

@@ -143,7 +143,8 @@ struct Pool
 {
 	DynArray da;
 
-	// size of elements; see pool_create.
+	// size of elements. = 0 if pool set up for variable-sized
+	// elements, otherwise rounded up to pool alignment.
 	size_t el_size;
 
 	// pointer to freelist (opaque); see freelist_*.
@@ -153,7 +154,7 @@ struct Pool
 
 // pass as pool_create's <el_size> param to indicate variable-sized allocs
 // are required (see below).
-const size_t POOL_VARIABLE_ALLOCS = 0;
+const size_t POOL_VARIABLE_ALLOCS = ~0u;
 
 // ready <p> for use. <max_size> is the upper limit [bytes] on
 // pool size (this is how much address space is reserved).

source/lib/lib.cpp

@@ -536,9 +536,9 @@ uint fullrand()
 }
 #endif
 
-uint rand(uint min, uint max)
+uint rand(uint min_inclusive, uint max_exclusive)
 {
-	const uint range = (max-min);
+	const uint range = (max_exclusive-min_inclusive);
 	// huge interval or min >= max
 	if(range == 0 || range > XRAND_MAX)
 	{
@@ -555,8 +555,8 @@ uint rand(uint min, uint max)
 	while(x >= range * inv_range);
 	x /= inv_range;
 
-	x += min;
-	debug_assert(x < max);
+	x += min_inclusive;
+	debug_assert(x < max_exclusive);
 	return x;
 }
 

source/lib/lib.h

@@ -311,6 +311,6 @@ extern int match_wildcardw(const wchar_t* s, const wchar_t* w);
 // return random integer in [min, max).
 // avoids several common pitfalls; see discussion at
 // http://www.azillionmonkeys.com/qed/random.html
-extern uint rand(uint min, uint max);
+extern uint rand(uint min_inclusive, uint max_exclusive);
 
 #endif	// #ifndef LIB_H__

source/lib/res/file/file.cpp

@@ -619,6 +619,29 @@ const char* file_make_unique_fn_copy(const char* P_fn)
 	return unique_fn;
 }
 
+
+const char* file_get_random_name()
+{
+	// there had better be names in atom_pool, else this will fail.
+	debug_assert(atom_pool.da.pos != 0);
+
+again:
+	const size_t start_ofs = (size_t)rand(0, (uint)atom_pool.da.pos-1);
+	
+	// scan ahead to next string boundary
+	const char* start = (const char*)atom_pool.da.base+start_ofs;
+	const char* next_0 = strchr(start, '\0')+1;
+	// .. at end of storage: restart
+	if((u8*)next_0 >= atom_pool.da.base+atom_pool.da.pos)
+		goto again;
+	// .. skip all '\0' (may be several due to pool alignment)
+	const char* next_name = next_0;
+	while(*next_name == '\0') next_name++;
+
+	return next_name;
+}
+
+
 static inline void atom_init()
 {
 	pool_create(&atom_pool, 8*MiB, POOL_VARIABLE_ALLOCS);

source/lib/res/file/file.h

@@ -94,6 +94,8 @@ extern LibError file_set_root_dir(const char* argv0, const char* rel_path);
 // (normal case) or the string length [characters].
 extern const char* file_make_unique_fn_copy(const char* P_fn);
 
+extern const char* file_get_random_name();
+
 
 //
 // dir_next_ent
@@ -328,15 +330,6 @@ extern LibError file_io_validate(const FileIo* io);
 const size_t FILE_BLOCK_SIZE = 32*KiB;
 
 
-typedef const u8* FileIOBuf;
-
-FileIOBuf* const FILE_BUF_TEMP = (FileIOBuf*)1;
-const FileIOBuf FILE_BUF_ALLOC = (FileIOBuf)2;
-
-extern FileIOBuf file_buf_alloc(size_t size, const char* atom_fn, bool long_lived);
-extern LibError file_buf_free(FileIOBuf buf);
-
-
 // called by file_io after a block IO has completed.
 // *bytes_processed must be set; file_io will return the sum of these values.
 // example: when reading compressed data and decompressing in the callback,
@@ -350,6 +343,15 @@ extern LibError file_buf_free(FileIOBuf buf);
 // anyway.
 typedef LibError (*FileIOCB)(uintptr_t ctx, const void* block, size_t size, size_t* bytes_processed);
 
+
+typedef const u8* FileIOBuf;
+
+FileIOBuf* const FILE_BUF_TEMP = (FileIOBuf*)1;
+const FileIOBuf FILE_BUF_ALLOC = (FileIOBuf)2;
+
+#include "file_cache.h"	// file_buf_*
+
+
 // transfer <size> bytes, starting at <ofs>, to/from the given file.
 // (read or write access was chosen at file-open time).
 //

source/lib/res/file/file_cache.cpp

@@ -401,6 +401,10 @@ success:
 	// p and size are the exact (non-padded) values as in dealloc.
 	void make_read_only(u8* p, size_t size)
 	{
+		// bail to avoid mprotect failing
+		if(!size)
+			return;
+
 		const size_t size_pa = round_up(size, BUF_ALIGN);
 		(void)mprotect(p, size_pa, PROT_READ);
 	}
@@ -701,8 +705,7 @@ public:
 
 	// add given buffer to extant list.
 	// long_lived indicates if this buffer will not be freed immediately
-	// (more precisely, before allocating the next buffer); see the
-	// FILE_LONG_LIVED flag.
+	// (more precisely: before allocating the next buffer); see FC_LONG_LIVED.
 	// note: reuses a previous extant_bufs[] slot if one is unused.
 	void add(FileIOBuf buf, size_t size, const char* atom_fn, bool long_lived)
 	{
@@ -992,12 +995,12 @@ static void free_padded_buf(FileIOBuf padded_buf, size_t size)
 // fragmentation). never returns 0.
 // <atom_fn>: owner filename (buffer is intended to be used for data from
 //   this file).
-// <long_lived>: indicates the buffer will not be freed immediately
-//   (i.e. before the next buffer alloc) as it normally should.
-//   this flag serves to suppress a warning and better avoid fragmentation.
-//   caller sets this when FILE_LONG_LIVED is specified.
-FileIOBuf file_buf_alloc(size_t size, const char* atom_fn, bool long_lived)
+// <fc_flags>: see FileCacheFlags.
+FileIOBuf file_buf_alloc(size_t size, const char* atom_fn, uint fc_flags)
 {
+	const bool should_update_stats = (fc_flags & FC_NO_STATS) == 0;
+	const bool long_lived = (fc_flags & FC_LONG_LIVED) != 0;
+
 	FileIOBuf buf;
 	uint attempts = 0;
 	for(;;)
@@ -1035,7 +1038,8 @@ FileIOBuf file_buf_alloc(size_t size, const char* atom_fn, bool long_lived)
 
 	extant_bufs.add(buf, size, atom_fn, long_lived);
 
-	stats_buf_alloc(size, round_up(size, BUF_ALIGN));
+	if(should_update_stats)
+		stats_buf_alloc(size, round_up(size, BUF_ALIGN));
 	return buf;
 }
 
@@ -1043,8 +1047,10 @@ FileIOBuf file_buf_alloc(size_t size, const char* atom_fn, bool long_lived)
 // mark <buf> as no longer needed. if its reference count drops to 0,
 // it will be removed from the extant list. if it had been added to the
 // cache, it remains there until evicted in favor of another buffer.
-LibError file_buf_free(FileIOBuf buf)
+LibError file_buf_free(FileIOBuf buf, uint fc_flags)
 {
+	const bool should_update_stats = (fc_flags & FC_NO_STATS) == 0;
+
 	if(!buf)
 		return ERR_OK;
 
@@ -1071,7 +1077,8 @@ LibError file_buf_free(FileIOBuf buf)
 		}
 	}
 
-	stats_buf_free();
+	if(should_update_stats)
+		stats_buf_free();
 	trace_notify_free(atom_fn, size);
 
 	return ERR_OK;
@@ -1082,15 +1089,15 @@ LibError file_buf_free(FileIOBuf buf)
 // file buffer if necessary.
 // called by file_io and afile_read.
 LibError file_buf_get(FileIOBuf* pbuf, size_t size,
-	const char* atom_fn, uint flags, FileIOCB cb)
+	const char* atom_fn, uint file_flags, FileIOCB cb)
 {
 	// decode *pbuf - exactly one of these is true
 	const bool temp  = (pbuf == FILE_BUF_TEMP);
 	const bool alloc = !temp && (*pbuf == FILE_BUF_ALLOC);
 	const bool user  = !temp && !alloc;
 
-	const bool is_write = (flags & FILE_WRITE) != 0;
-	const bool long_lived = (flags & FILE_LONG_LIVED) != 0;
+	const bool is_write = (file_flags & FILE_WRITE) != 0;
+	const uint fc_flags = (file_flags & FILE_LONG_LIVED)? FC_LONG_LIVED : 0;
 
 	// reading into temp buffers - ok.
 	if(!is_write && temp && cb != 0)
@@ -1099,7 +1106,7 @@ LibError file_buf_get(FileIOBuf* pbuf, size_t size,
 	// reading and want buffer allocated.
 	if(!is_write && alloc)
 	{
-		*pbuf = file_buf_alloc(size, atom_fn, long_lived);
+		*pbuf = file_buf_alloc(size, atom_fn, fc_flags);
 		if(!*pbuf)	// very unlikely (size totally bogus or cache hosed)
 			WARN_RETURN(ERR_NO_MEM);
 		return ERR_OK;
@@ -1156,6 +1163,8 @@ LibError file_cache_add(FileIOBuf buf, size_t size, const char* atom_fn)
 
 	// decide (based on flags) if buf is to be cached; set cost
 	uint cost = 1;
+	if(!size)
+		cost = 0;
 
 	ExactBufOracle::BufAndSize bas = exact_buf_oracle.get(buf, size);
 	FileIOBuf exact_buf = bas.first; size_t exact_size = bas.second;
@@ -1167,38 +1176,34 @@ LibError file_cache_add(FileIOBuf buf, size_t size, const char* atom_fn)
 }
 
 
-// called by trace simulator to retrieve buffer address, given atom_fn.
-// must not change any cache state (e.g. notify stats or add ref).
-FileIOBuf file_cache_find(const char* atom_fn, size_t* psize)
-{
-	FileIOBuf buf;
-	bool should_refill_credit = false;
-	if(!file_cache.retrieve(atom_fn, buf, psize, should_refill_credit))
-		return 0;
-	return buf;
-}
 
 
 // check if the contents of the file <atom_fn> are in file cache.
 // if not, return 0; otherwise, return buffer address and optionally
 // pass back its size.
-// <long_lived> indicates whether this file has FILE_LONG_LIVED flag set -
-// see file_buf_alloc docs.
-FileIOBuf file_cache_retrieve(const char* atom_fn, size_t* psize, bool long_lived)
+//
+// note: does not call stats_cache because it does not know the file size
+// in case of cache miss! doing so is left to the caller.
+FileIOBuf file_cache_retrieve(const char* atom_fn, size_t* psize, uint fc_flags)
 {
 	// note: do not query extant_bufs - reusing that doesn't make sense
 	// (why would someone issue a second IO for the entire file while
 	// still referencing the previous instance?)
 
-	FileIOBuf buf = file_cache_find(atom_fn, psize);
-	if(buf)
-	{
-		extant_bufs.add_ref(buf, *psize, atom_fn, long_lived);
-		stats_buf_ref();
-	}
+	const bool long_lived = (fc_flags & FC_LONG_LIVED) != 0;
+	const bool should_account = (fc_flags & FC_NO_ACCOUNTING) == 0;
+	const bool should_update_stats = (fc_flags & FC_NO_STATS) == 0;
 
-	CacheRet cr = buf? CR_HIT : CR_MISS;
-	stats_cache(cr, *psize, atom_fn);
+	FileIOBuf buf;
+	const bool should_refill_credit = should_account;
+	if(!file_cache.retrieve(atom_fn, buf, psize, should_refill_credit))
+		return 0;
+
+	if(should_account)
+		extant_bufs.add_ref(buf, *psize, atom_fn, long_lived);
+
+	if(should_update_stats)
+		stats_buf_ref();
 
 	return buf;
 }

source/lib/res/file/file_cache.h

@@ -1,3 +1,5 @@
+#ifndef FILE_CACHE_H__
+#define FILE_CACHE_H__
 
 struct BlockId
 {
@@ -20,20 +22,38 @@ extern void block_cache_release(BlockId id);
 
 
 
+
+enum FileCacheFlags
+{
+	// indicates the buffer will not be freed immediately
+	// (i.e. before the next buffer alloc) as it normally should.
+	// this flag serves to suppress a warning and better avoid fragmentation.
+	// caller sets this when FILE_LONG_LIVED is specified.
+	//
+	// also used by file_cache_retrieve because it may have to
+	// 'reactivate' the buffer (transfer from cache to extant list),
+	// which requires knowing whether the buffer is long-lived or not.
+	FC_LONG_LIVED    = 1,
+
+	// statistics (e.g. # buffer allocs) should not be updated.
+	// (useful for simulation, e.g. trace_entry_causes_io)
+	FC_NO_STATS      = 2,
+
+	// file_cache_retrieve should not update item credit.
+	// (useful when just looking up buffer given atom_fn)
+	FC_NO_ACCOUNTING = 4
+};
+
 // allocate a new buffer of <size> bytes (possibly more due to internal
 // fragmentation). never returns 0.
 // <atom_fn>: owner filename (buffer is intended to be used for data from
 //   this file).
-// <long_lived>: indicates the buffer will not be freed immediately
-//   (i.e. before the next buffer alloc) as it normally should.
-//   this flag serves to suppress a warning and better avoid fragmentation.
-//   caller sets this when FILE_LONG_LIVED is specified.
-extern FileIOBuf file_buf_alloc(size_t size, const char* atom_fn, bool long_lived);
+extern FileIOBuf file_buf_alloc(size_t size, const char* atom_fn, uint fc_flags = 0);
 
 // mark <buf> as no longer needed. if its reference count drops to 0,
 // it will be removed from the extant list. if it had been added to the
 // cache, it remains there until evicted in favor of another buffer.
-extern LibError file_buf_free(FileIOBuf buf);
+extern LibError file_buf_free(FileIOBuf buf, uint fc_flags = 0);
 
 // interpret file_io parameters (pbuf, size, flags, cb) and allocate a
 // file buffer if necessary.
@@ -66,16 +86,15 @@ extern LibError file_buf_set_real_fn(FileIOBuf buf, const char* atom_fn);
 // still be file_buf_free-d after calling this.
 extern LibError file_cache_add(FileIOBuf buf, size_t size, const char* atom_fn);
 
-// called by trace simulator to retrieve buffer address, given atom_fn.
-// must not change any cache state (e.g. notify stats or add ref).
-extern FileIOBuf file_cache_find(const char* atom_fn, size_t* psize);
+
 
 // check if the contents of the file <atom_fn> are in file cache.
 // if not, return 0; otherwise, return buffer address and optionally
 // pass back its size.
-// <long_lived> indicates whether this file has FILE_LONG_LIVED flag set -
-// see file_buf_alloc docs.
-extern FileIOBuf file_cache_retrieve(const char* atom_fn, size_t* psize, bool long_lived);
+//
+// note: does not call stats_cache because it does not know the file size
+// in case of cache miss! doing so is left to the caller.
+extern FileIOBuf file_cache_retrieve(const char* atom_fn, size_t* psize, uint fc_flags = 0);
 
 // invalidate all data loaded from the file <fn>. this ensures the next
 // load of this file gets the (presumably new) contents of the file,
@@ -91,3 +110,5 @@ extern void file_cache_reset();
 
 extern void file_cache_init();
 extern void file_cache_shutdown();
+
+#endif	// #ifndef FILE_CACHE_H__

source/lib/res/file/file_io.cpp

@@ -116,6 +116,9 @@ LibError file_io_issue(File* f, off_t ofs, size_t size, void* p, FileIo* io)
 		WARN_RETURN(LibError_from_errno());
 	}
 
+	const BlockId disk_pos = block_cache_make_id(f->fc.atom_fn, ofs);
+	stats_io_check_seek(disk_pos);
+
 	return ERR_OK;
 }
 
@@ -281,9 +284,6 @@ class IOManager
 
 		void* temp_buf;
 
-		// used by stats_io_start/finish to measure throughput
-		double start_time;
-
 		IOSlot()
 		{
 			reset();
@@ -294,7 +294,6 @@ class IOManager
 			cached_block = 0;
 			memset(&block_id, 0, sizeof(block_id));
 			temp_buf = 0;
-			start_time = 0.0;	// required for stats
 		}
 	};
 	static const uint MAX_PENDING_IOS = 4;
@@ -536,11 +535,10 @@ public:
 
 		const FileIOImplentation fi = no_aio? FI_LOWIO : FI_AIO;
 		const FileOp fo = is_write? FO_WRITE : FO_READ;
-		const BlockId disk_pos = block_cache_make_id(f->fc.atom_fn, start_ofs);
 		double start_time = 0.0;
-		stats_io_start(disk_pos, &start_time);
-			ssize_t ret = no_aio? lowio() : aio();
-		stats_io_finish(fi, fo, ret, &start_time);
+		stats_io_sync_start(&start_time);
+			ssize_t bytes_transferred = no_aio? lowio() : aio();
+		stats_io_sync_finish(fi, fo, bytes_transferred, &start_time);
 
 		// we allocated the memory: skip any leading padding
 		if(pbuf != FILE_BUF_TEMP && !is_write)
@@ -553,7 +551,7 @@ public:
 
 		if(err != INFO_CB_CONTINUE && err != ERR_OK)
 			return (ssize_t)err;
-		return ret;
+		return bytes_transferred;
 	}
 
 };	// IOManager

source/lib/res/file/file_stats.cpp

@@ -31,7 +31,6 @@ static double user_io_size_total;
 static double io_actual_size_total[FI_MAX_IDX][2];
 static double io_elapsed_time[FI_MAX_IDX][2];
 static double io_process_time_total;
-static BlockId io_disk_pos_cur;
 static uint io_seeks;
 
 // file_cache
@@ -42,6 +41,9 @@ static uint conflict_misses;
 static double conflict_miss_size_total;
 static uint block_cache_count[2];
 
+// archive builder
+static uint ab_connection_attempts;	// total number of trace entries
+static uint ab_repeated_connections;	// how many of these were not unique
 
 
 // convenience functions for measuring elapsed time in an interval.
@@ -151,23 +153,22 @@ void stats_buf_ref()
 // file_io
 //
 
-void stats_user_io(size_t user_size)
+void stats_io_user_request(size_t user_size)
 {
 	user_ios++;
 	user_io_size_total += user_size;
 }
 
-void stats_io_start(BlockId disk_pos, double* start_time_storage)
+// these bracket file_io's IOManager::run and measure effective throughput.
+// note: cannot be called from aio issue/finish because IOManager's
+// decompression may cause us to miss the exact end of IO, thus throwing off
+// throughput measurements.
+void stats_io_sync_start(double* start_time_storage)
 {
-	if(disk_pos.atom_fn != io_disk_pos_cur.atom_fn ||
-	   disk_pos.block_num != io_disk_pos_cur.block_num+1)
-		io_seeks++;
-	io_disk_pos_cur = disk_pos;
-
 	timer_start(start_time_storage);
 }
 
-void stats_io_finish(FileIOImplentation fi, FileOp fo, ssize_t user_size, double* start_time_storage)
+void stats_io_sync_finish(FileIOImplentation fi, FileOp fo, ssize_t user_size, double* start_time_storage)
 {
 	debug_assert(fi < FI_MAX_IDX);
 	debug_assert(fo == FO_READ || FO_WRITE);
@@ -180,6 +181,25 @@ void stats_io_finish(FileIOImplentation fi, FileOp fo, ssize_t user_size, double
 	}
 }
 
+
+void stats_io_check_seek(BlockId disk_pos)
+{
+	static BlockId cur_disk_pos;
+
+	// makes debugging ("why are there seeks") a bit nicer by suppressing
+	// the first (bogus) seek.
+	if(!cur_disk_pos.atom_fn)
+		goto dont_count_first_seek;
+
+	if(disk_pos.atom_fn != cur_disk_pos.atom_fn ||	// different file OR
+	   disk_pos.block_num != cur_disk_pos.block_num+1)	// nonsequential
+		io_seeks++;
+
+dont_count_first_seek:
+	cur_disk_pos = disk_pos;
+}
+
+
 void stats_cb_start()
 {
 	timer_start();
@@ -220,6 +240,18 @@ void stats_block_cache(CacheRet cr)
 }
 
 
+//
+// archive builder
+//
+
+void stats_ab_connection(bool already_exists)
+{
+	ab_connection_attempts++;
+	if(already_exists)
+		ab_repeated_connections++;
+}
+
+
 //-----------------------------------------------------------------------------
 
 template<typename T> int percent(T num, T divisor)
@@ -239,18 +271,16 @@ void stats_dump()
 	// note: we split the reports into several debug_printfs for clarity;
 	// this is necessary anyway due to fixed-size buffer.
 
-	// vfs
 	debug_printf(
-		"\n"
+		"\nvfs:\n"
 		"Total files: %u (%g MB)\n"
 		"Init/mount time: %g ms\n",
 		vfs_files, vfs_size_total/MB,
 		vfs_init_elapsed_time/ms
 	);
 
-	// file
 	debug_printf(
-		"\n"
+		"\nfile:\n"
 		"Total names: %u (%u KB)\n"
 		"Accessed files: %u (%g MB) -- %u%% of data set\n"
 		"Max. concurrent: %u; leaked: %u.\n",
@@ -259,9 +289,8 @@ void stats_dump()
 		open_files_max, open_files_cur
 	);
 
-	// file_buf
 	debug_printf(
-		"\n"
+		"\nfile_buf:\n"
 		"Total buffers used: %u (%g MB)\n"
 		"Max concurrent: %u; leaked: %u\n"
 		"Internal fragmentation: %d%%\n",
@@ -270,24 +299,24 @@ void stats_dump()
 		percent(buf_padded_size_total-buf_user_size_total, buf_user_size_total)
 	);
 
-	// file_io
 	debug_printf(
-		"\n"
-		"Total user IOs: %u (%g MB)\n"
+		"\nfile_io:\n"
+		"Total user load requests: %u (%g MB)\n"
 		"IO thoughput [MB/s; 0=never happened]:\n"
 		"  lowio: R=%.3g, W=%.3g\n"
 		"    aio: R=%.3g, W=%.3g\n"
-		"Average size = %g KB; seeks: %u; total callback time: %g ms\n",
+		"Average size = %g KB; seeks: %u; total callback time: %g ms\n"
+		"Total data actually read from disk = %g MB\n",
 		user_ios, user_io_size_total/MB,
 #define THROUGHPUT(impl, op) (io_elapsed_time[impl][op] == 0.0)? 0.0 : (io_actual_size_total[impl][op] / io_elapsed_time[impl][op] / MB)
 		THROUGHPUT(FI_LOWIO, FO_READ), THROUGHPUT(FI_LOWIO, FO_WRITE),
 		THROUGHPUT(FI_AIO  , FO_READ), THROUGHPUT(FI_AIO  , FO_WRITE),
-		user_io_size_total/user_ios/KB, io_seeks, io_process_time_total/ms
+		user_io_size_total/user_ios/KB, io_seeks, io_process_time_total/ms,
+		(io_actual_size_total[FI_LOWIO][FO_READ]+io_actual_size_total[FI_AIO][FO_READ])/MB
 	);
 
-	// file_cache
 	debug_printf(
-		"\n"
+		"\nfile_cache:\n"
 		"Hits: %u (%g MB); misses %u (%g MB)\n"
 		"Hit ratio: %u%%; conflict misses: %u%%\n"
 		"Block hits: %u; misses: %u; ratio: %u%%\n",
@@ -295,4 +324,10 @@ void stats_dump()
 		percent(cache_count[CR_HIT], cache_count[CR_MISS]), percent(conflict_misses, cache_count[CR_MISS]),
 		block_cache_count[CR_HIT], block_cache_count[CR_MISS], percent(block_cache_count[CR_HIT], block_cache_count[CR_HIT]+block_cache_count[CR_MISS])
 	);
+
+	debug_printf(
+		"\nvfs_optimizer:\n"
+		"Total trace entries: %u; repeated connections: %u; unique files: %u\n",
+		ab_connection_attempts, ab_repeated_connections, ab_connection_attempts-ab_repeated_connections
+	);
 }

source/lib/res/file/file_stats.h

@@ -28,9 +28,10 @@ extern void stats_buf_free();
 extern void stats_buf_ref();
 
 // file_io
-extern void stats_user_io(size_t user_size);
-extern void stats_io_start(BlockId disk_pos, double* start_time_storage);
-extern void stats_io_finish(FileIOImplentation fi, FileOp fo, ssize_t user_size, double* start_time_storage);
+extern void stats_io_user_request(size_t user_size);
+extern void stats_io_sync_start(double* start_time_storage);
+extern void stats_io_sync_finish(FileIOImplentation fi, FileOp fo, ssize_t user_size, double* start_time_storage);
+extern void stats_io_check_seek(BlockId disk_pos);
 extern void stats_cb_start();
 extern void stats_cb_finish();
 
@@ -38,6 +39,9 @@ extern void stats_cb_finish();
 extern void stats_cache(CacheRet cr, size_t size, const char* atom_fn);
 extern void stats_block_cache(CacheRet cr);
 
+// archive builder
+extern void stats_ab_connection(bool already_exists);
+
 extern void stats_dump();
 
 #else
@@ -52,13 +56,15 @@ extern void stats_dump();
 #define stats_buf_alloc(user_size, padded_size)
 #define stats_buf_free()
 #define stats_buf_ref()
-#define stats_user_io(user_size)
-#define stats_io_start(disk_pos, start_time_storage)
-#define stats_io_finish(fi, fo, user_size, start_time_storage)
+#define stats_io_user_request(user_size)
+#define stats_io_sync_start(disk_pos, start_time_storage)
+#define stats_io_sync_finish(fi, fo, user_size, start_time_storage)
+#define stats_io_check_seek(disk_pos)
 #define stats_cb_start()
 #define stats_cb_finish()
 #define stats_cache(cr, size, atom_fn)
 #define stats_block_cache(cr)
+#define stats_ab_connection(already_exists)
 #define stats_dump()
 
 #endif

source/lib/res/file/trace.cpp

@@ -167,12 +167,49 @@ LibError trace_read_from_file(const char* trace_filename, Trace* t)
 }
 
 
+void trace_gen_random(size_t num_entries)
+{
+	trace_clear();
+
+	for(size_t i = 0; i < num_entries; i++)
+	{
+		// generate random names until we get a valid file;
+		// remember its name and size.
+		const char* atom_fn;
+		off_t size;
+		for(;;)
+		{
+			atom_fn = file_get_random_name();
+			// use instead of vfs_stat to avoid warnings, since some of
+			// atom_fn will actually be directory names.
+			if(vfs_exists(atom_fn))
+			{
+				struct stat s;
+				LibError ret = vfs_stat(atom_fn, &s);
+				// ought to apply due to vfs_exists above.
+				debug_assert(ret == ERR_OK && S_ISREG(s.st_mode));
+
+				size = s.st_size;
+				break;
+			}
+		}
+
+		trace_add(TO_LOAD, atom_fn, size);
+		trace_add(TO_FREE, atom_fn, size);
+	}
+}
+
+
 //-----------------------------------------------------------------------------
 
 // simulate carrying out the entry's TraceOp to determine
 // whether this IO would be satisfied by the file_buf cache.
 bool trace_entry_causes_io(const TraceEntry* ent)
 {
+	uint fc_flags = FC_NO_STATS;
+	if(ent->flags & FILE_LONG_LIVED)
+		fc_flags |= FC_LONG_LIVED;
+
 	FileIOBuf buf;
 	size_t size         = ent->size;
 	const char* atom_fn = ent->atom_fn;
@@ -180,19 +217,18 @@ bool trace_entry_causes_io(const TraceEntry* ent)
 	{
 	case TO_LOAD:
 	{
-		bool long_lived = (ent->flags & FILE_LONG_LIVED) != 0;
-		buf = file_cache_retrieve(atom_fn, &size, long_lived);
+		buf = file_cache_retrieve(atom_fn, &size, fc_flags);
 		// would not be in cache: add to list of real IOs
 		if(!buf)
 		{
-			buf = file_buf_alloc(size, atom_fn, long_lived);
+			buf = file_buf_alloc(size, atom_fn, fc_flags);
 			(void)file_cache_add(buf, size, atom_fn);
 			return true;
 		}
 		break;
 	}
 	case TO_FREE:
-		buf = file_cache_find(atom_fn, &size);
+		buf = file_cache_retrieve(atom_fn, &size, fc_flags|FC_NO_ACCOUNTING);
 		(void)file_buf_free(buf);
 		break;
 	default:
@@ -238,7 +274,7 @@ LibError trace_run(const char* trace_filename, uint flags)
 			(void)vfs_load(ent->atom_fn, buf, size, ent->flags);
 			break;
 		case TO_FREE:
-			buf = file_cache_find(ent->atom_fn, &size);
+			buf = file_cache_retrieve(ent->atom_fn, &size, FC_NO_STATS|FC_NO_ACCOUNTING);
 			(void)file_buf_free(buf);
 			break;
 		default:

source/lib/res/file/trace.h

@@ -45,6 +45,8 @@ extern void trace_get(Trace* t);
 extern LibError trace_write_to_file(const char* trace_filename);
 extern LibError trace_read_from_file(const char* trace_filename, Trace* t);
 
+extern void trace_gen_random(size_t num_entries);
+
 
 // simulate carrying out the entry's TraceOp to determine
 // whether this IO would be satisfied by the file_buf cache.

source/lib/res/file/vfs.cpp

@@ -423,7 +423,7 @@ ssize_t vfs_io(const Handle hf, const size_t size, FileIOBuf* pbuf,
 	H_DEREF(hf, VFile, vf);
 	FileCommon* fc = &vf->xf.u.fc;
 
-	stats_user_io(size);
+	stats_io_user_request(size);
 	trace_notify_load(fc->atom_fn, size, fc->flags);
 
 	off_t ofs = vf->ofs;
@@ -445,14 +445,15 @@ LibError vfs_load(const char* V_fn, FileIOBuf& buf, size_t& size,
 	debug_printf("VFS| load: V_fn=%s\n", V_fn);
 
 	const char* atom_fn = file_make_unique_fn_copy(V_fn);
-	bool long_lived = (flags & FILE_LONG_LIVED) != 0;
-	buf = file_cache_retrieve(atom_fn, &size, long_lived);
+	const uint fc_flags = (flags & FILE_LONG_LIVED)? FC_LONG_LIVED : 0;
+	buf = file_cache_retrieve(atom_fn, &size, fc_flags);
 	if(buf)
 	{
 		// we want to skip the below code (especially vfs_open) for
 		// efficiency. that includes stats/trace accounting, though,
 		// so duplicate that here:
-		stats_user_io(size);
+		stats_cache(CR_HIT, size, atom_fn);
+		stats_io_user_request(size);
 		trace_notify_load(atom_fn, size, flags);
 
 		size_t actual_size;
@@ -491,7 +492,9 @@ LibError vfs_load(const char* V_fn, FileIOBuf& buf, size_t& size,
 	}
 
 	debug_assert(nread == (ssize_t)size);
+
 	(void)file_cache_add(buf, size, atom_fn);
+	stats_cache(CR_MISS, size, atom_fn);
 
 	(void)vfs_close(hf);
 	return ERR_OK;

source/lib/res/file/vfs_optimizer.cpp

@@ -278,14 +278,18 @@ class ConnectionBuilder
 			Connection* next_c = &connections[0] + connections.size();
 			const std::pair<ConnectionId, Connection*> item = std::make_pair(c_id, next_c);
 			std::pair<Map::iterator, bool> ret = map.insert(item);
-			if(!ret.second)	// already existed
+			const bool already_exists = !ret.second;
+			if(already_exists)
 			{
 				Map::iterator inserted_at = ret.first;
 				Connection* c = inserted_at->second;	// std::map "payload"
 				c->occurrences++;
 			}
-			else	// first time we've seen this connection
+			// first time we've seen this connection
+			else
 				connections.push_back(Connection(c_id));
+
+			stats_ab_connection(already_exists);
 		}
 	};