improve disk stats logging to include cache hits

examples/fragmentation_test.cpp

@@ -112,7 +112,7 @@ int main(int argc, char const* argv[])
 		"set output \"fragmentation.png\"\n"
 		"set xrange [*:*]\n"
 		"set xlabel \"piece\"\n"
-		"set ylabel \"file position\"\n"
+		"set ylabel \"drive offset\"\n"
 		"set key box\n"
 		"set title \"fragmentation for '%s'\"\n"
 		"set tics nomirror\n"

include/libtorrent/disk_io_thread.hpp

@@ -379,7 +379,7 @@ namespace libtorrent
 			, int options, int num_blocks, mutex::scoped_lock& l);
 		int cache_read_block(disk_io_job const& j, mutex::scoped_lock& l);
 		int free_piece(cached_piece_entry& p, mutex::scoped_lock& l);
-		int try_read_from_cache(disk_io_job const& j);
+		int try_read_from_cache(disk_io_job const& j, bool& hit);
 		int read_piece_from_cache_and_hash(disk_io_job const& j, sha1_hash& h);
 		int cache_piece(disk_io_job const& j, cache_piece_index_t::iterator& p
 			, bool& hit, int options, mutex::scoped_lock& l);

parse_disk_access.py

@@ -5,25 +5,28 @@ import os, sys, time
 lines = open(sys.argv[1], 'rb').readlines()
 
 # logfile format:
-# <time(ms)> <key>: <value>
+# <time(us)> <key>: <value>
 # example:
 # 16434 read cache: 17
 
-keys = ['read', 'write', 'head movement', 'seek per read byte', 'seek per written byte']
-colors = ['70e070', 'e07070', '3030f0', '10a010', 'a01010']
-style = ['linespoints', 'points pointtype 2', 'lines', 'lines', 'lines']
-axis = ['x1y1', 'x1y1', 'x1y2', 'x1y2', 'x1y2']
-plot = [True, False, False, False, False]
+keys = ['read', 'write', 'head movement', 'seek per read byte', 'seek per written byte',
+	'read operations per second', 'write operations per second']
+colors = ['305030', '503030', '3030f0', '10a010', 'a01010', 'd0d040', 'd040d0']
+style = ['dots', 'points', 'lines', 'lines', 'lines', 'lines', 'lines']
+axis = ['x1y1', 'x1y1', 'x1y2', 'x1y2', 'x1y2', 'x1y2', 'x1y2']
+plot = [True, False, False, False, False, True, False]
 
 out = open('disk_access_log.dat', 'w+')
 
-time = 1000
+time = 1000000
 
 last_pos = 0
 last_t = 0
 cur_movement = 0
 cur_read = 0
 cur_write = 0
+cur_read_ops = 0
+cur_write_ops = 0
 
 for l in lines:
 	try:
@@ -41,8 +44,14 @@ for l in lines:
 	movement = '-'
 	amount_read = '-'
 	amount_write = '-'
-	if k == 'read': read = '%d' % n
-	if k == 'write': write = '%d' % n
+	read_ops = '-'
+	write_ops = '-'
+	if k == 'read':
+		read = '%d' % n
+		cur_read_ops += 1
+	if k == 'write':
+		write = '%d' % n
+		cur_write_ops += 1
 	if k == 'read_end': cur_read += n - last_pos
 	if k == 'write_end': cur_write += n - last_pos
 
@@ -55,26 +64,30 @@ for l in lines:
 			amount_read = '%d' % (cur_movement / cur_read)
 		if cur_write > 0:
 			amount_write = '%d' % (cur_movement / cur_write)
+		read_ops = '%d' % cur_read_ops
+		write_ops = '%d' % cur_write_ops
 		cur_movement = 0
 		cur_read = 0
 		cur_write = 0
 		last_t = t
+		cur_read_ops = 0
+		cur_write_ops = 0
 
-	print >>out, '%d\t%s\t%s\t%s\t%s\t%s' % (t, read, write, movement, amount_read, amount_write)
+	print >>out, '%d\t%s\t%s\t%s\t%s\t%s\t%s\t%s' % (t, read, write, movement, amount_read, amount_write, read_ops, write_ops)
 
 out.close()
 
 out = open('disk_access.gnuplot', 'wb')
-print >>out, "set term png size 1200,900"
+print >>out, "set term png size 1200,700"
 print >>out, 'set output "disk_access.png"'
 print >>out, 'set xrange [*:*]'
 #print >>out, 'set y2range [0:*]'
-print >>out, 'set xlabel "time (ms)"'
-print >>out, 'set ylabel "file position"'
+print >>out, 'set xlabel "time (us)"'
+print >>out, 'set ylabel "drive offset"'
 #print >>out, 'set y2label "bytes / %d second(s)"' % (time / 1000)
 print >>out, "set key box"
 print >>out, "set tics nomirror"
-#print >>out, "set y2tics 100"
+print >>out, "set y2tics auto"
 print >>out, 'plot',
 count = 1
 for k in keys:

parse_disk_log.py

@@ -11,12 +11,12 @@ if len(sys.argv) < 2:
 	print "usage: parse_disk_log.py logfile [seconds]"
 	sys.exit(1)
 
-keys = ['write', 'read', 'hash', 'move', 'release', 'idle', \
+keys = ['write', 'read', 'read-cache-hit', 'hash', 'move', 'release', 'idle', \
 	'delete', 'check_fastresume', 'check_files', 'clear-cache', \
 	'abort_thread', 'abort_torrent', 'save_resume_data', 'rename_file', \
 	'flushing', 'update_settings', 'finalize_file', 'sorting_job', \
 	'check_cache_hit']
-throughput_keys = ['write', 'read']
+throughput_keys = ['write', 'read', 'read-cache-hit']
 
 # logfile format:
 # <time(ms)> <state>
@@ -39,6 +39,7 @@ state_timer = {}
 throughput = {}
 for k in keys: state_timer[k] = 0
 for k in throughput_keys: throughput[k] = 0
+
 for l in lines:
 	l = l.strip().split()
 	if len(l) < 2:
@@ -58,7 +59,7 @@ for l in lines:
 		print >>out
 		print >>out2, time - start_time,
 		for k in throughput_keys:
-			print >>out2, throughput[k] / float(quantization),
+			print >>out2, throughput[k] * 1000 / float(quantization),
 			print '-- %s %d' % (k, throughput[k])
 		print >>out2
 		for k in keys: state_timer[k] = 0
@@ -78,7 +79,7 @@ for k in keys: print >>out, (state_timer[k] / float(quantization) * 100.),
 print >>out
 print >>out2, time - start_time,
 for k in throughput_keys:
-	print >>out2, throughput[k] / float(quantization),
+	print >>out2, throughput[k] * 1000 / float(quantization),
 	print '-- %s %d' % (k, throughput[k])
 print >>out2
 for k in keys: state_timer[k] = 0
@@ -95,7 +96,7 @@ print >>out, 'set ylabel "throughput (kB/s)"'
 print >>out, 'plot',
 i = 0
 for k in throughput_keys:
-	print >>out, ' "disk_throughput.dat" using 1:%d title "%s" with steps,' % (i + 2, throughput_keys[i]),
+	print >>out, ' "disk_throughput.dat" using 1:%d title "%s" with lines,' % (i + 2, throughput_keys[i]),
 	i = i + 1
 print >>out, 'x=0'
 

parse_session_stats.py

@@ -25,7 +25,8 @@ def gen_report(name, lines):
 	print >>out, 'set ylabel "number"'
 	print >>out, 'set y2label "Rate (B/s)"'
 	print >>out, 'set y2range [0:*]'
-	print >>out, 'set y2tics 10000'
+	print >>out, 'set y2tics auto'
+	print >>out, "set tics nomirror"
 	print >>out, "set style data lines"
 	print >>out, "set key box"
 	print >>out, 'plot',

src/disk_io_thread.cpp

@@ -1234,7 +1234,7 @@ namespace libtorrent
 		return j.buffer_size;
 	}
 
-	int disk_io_thread::try_read_from_cache(disk_io_job const& j)
+	int disk_io_thread::try_read_from_cache(disk_io_job const& j, bool& hit)
 	{
 		TORRENT_ASSERT(j.buffer);
 		TORRENT_ASSERT(j.cache_min_time >= 0);
@@ -1246,7 +1246,7 @@ namespace libtorrent
 		cache_piece_index_t::iterator p
 			= find_cached_piece(m_read_pieces, j, l);
 
-		bool hit = true;
+		hit = true;
 		int ret = 0;
 
 		// if the piece cannot be found in the cache,
@@ -1749,7 +1749,7 @@ namespace libtorrent
 						break;
 					}
 #ifdef TORRENT_DISK_STATS
-					m_log << log_time() << " read " << j.buffer_size << std::endl;
+					m_log << log_time();
 #endif
 					INVARIANT_CHECK;
 					TORRENT_ASSERT(j.buffer == 0);
@@ -1757,6 +1757,9 @@ namespace libtorrent
 					TORRENT_ASSERT(j.buffer_size <= m_block_size);
 					if (j.buffer == 0)
 					{
+#ifdef TORRENT_DISK_STATS
+						m_log << " read 0" << std::endl;
+#endif
 						ret = -1;
 #if BOOST_VERSION == 103500
 						j.error = error_code(boost::system::posix_error::not_enough_memory
@@ -1773,8 +1776,12 @@ namespace libtorrent
 
 					disk_buffer_holder read_holder(*this, j.buffer);
 
-					ret = try_read_from_cache(j);
+					bool hit;
+					ret = try_read_from_cache(j, hit);
 
+#ifdef TORRENT_DISK_STATS
+					m_log << (hit?" read-cache-hit ":" read ") << j.buffer_size << std::endl;
+#endif
 					// -2 means there's no space in the read cache
 					// or that the read cache is disabled
 					if (ret == -1)