From 238f7e38f539a2febf861bb9c12772474bd86d57 Mon Sep 17 00:00:00 2001 From: Arvid Norberg Date: Sun, 31 Jan 2010 21:13:52 +0000 Subject: [PATCH] improve disk stats logging to include cache hits --- examples/fragmentation_test.cpp | 2 +- include/libtorrent/disk_io_thread.hpp | 2 +- parse_disk_access.py | 41 ++++++++++++++++++--------- parse_disk_log.py | 11 +++---- parse_session_stats.py | 3 +- src/disk_io_thread.cpp | 15 +++++++--- 6 files changed, 48 insertions(+), 26 deletions(-) diff --git a/examples/fragmentation_test.cpp b/examples/fragmentation_test.cpp index 9ff6c42ca..6152da71e 100644 --- a/examples/fragmentation_test.cpp +++ b/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" diff --git a/include/libtorrent/disk_io_thread.hpp b/include/libtorrent/disk_io_thread.hpp index 58456d084..8a2bd3e73 100644 --- a/include/libtorrent/disk_io_thread.hpp +++ b/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); diff --git a/parse_disk_access.py b/parse_disk_access.py index de0c55d01..e3310a50c 100755 --- a/parse_disk_access.py +++ b/parse_disk_access.py @@ -5,25 +5,28 @@ import os, sys, time lines = open(sys.argv[1], 'rb').readlines() # logfile format: -# : +# : # 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: diff --git a/parse_disk_log.py b/parse_disk_log.py index f23f169c5..d8eeb8946 100755 --- a/parse_disk_log.py +++ b/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: # @@ -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' diff --git a/parse_session_stats.py b/parse_session_stats.py index b4e6169ee..2b980b427 100755 --- a/parse_session_stats.py +++ b/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', diff --git a/src/disk_io_thread.cpp b/src/disk_io_thread.cpp index 3913ccf56..b7d1696bb 100644 --- a/src/disk_io_thread.cpp +++ b/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)