From 06da1f8e8add33900e482bb828359d51cabc7255 Mon Sep 17 00:00:00 2001 From: Arvid Norberg Date: Tue, 30 Dec 2008 08:20:25 +0000 Subject: [PATCH] added some session logging. added more disk-io-thread stats logging and parse script --- parse_disk_log.py | 42 +++++++++++++++++++++--------------------- src/disk_io_thread.cpp | 14 ++++++++++---- src/session_impl.cpp | 5 ++++- src/torrent.cpp | 8 ++++++-- 4 files changed, 41 insertions(+), 28 deletions(-) diff --git a/parse_disk_log.py b/parse_disk_log.py index 8b337f1a5..b739c8869 100755 --- a/parse_disk_log.py +++ b/parse_disk_log.py @@ -11,7 +11,7 @@ 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', 'hash', 'move', 'release', 'idle', 'delete', 'check_fastresume', 'check_files', 'clear-cache', 'abort_thread', 'abort_torrent', 'save_resume_data', 'rename_file', 'flushing'] throughput_keys = ['write', 'read'] # logfile format: @@ -35,29 +35,29 @@ throughput = {} for k in keys: state_timer[k] = 0 for k in throughput_keys: throughput[k] = 0 for l in lines: - l = l[:-1].split(' ') + l = l.strip().split() if len(l) < 2: print l continue - try: - new_time = long(l[0]) - while new_time > i + quantization: - i += quantization - state_timer[state] += i - time - time = i - for k in keys: print >>out, state_timer[k], - print >>out - for k in throughput_keys: print >>out2, throughput[k] / 1000., - print >>out2 - for k in keys: state_timer[k] = 0 - for k in throughput_keys: throughput[k] = 0 - state_timer[state] += new_time - time - time = new_time - state = l[1] - if state in throughput_keys: - throughput[state] += long(l[2]) - except: - print l +# try: + new_time = long(l[0]) + while new_time > i + quantization: + i += quantization + state_timer[state] += i - time + time = i + for k in keys: print >>out, state_timer[k], + print >>out + for k in throughput_keys: print >>out2, throughput[k] / 1000., + print >>out2 + for k in keys: state_timer[k] = 0 + for k in throughput_keys: throughput[k] = 0 + state_timer[state] += new_time - time + time = new_time + state = l[1] + if state in throughput_keys: + throughput[state] += long(l[2]) +# except: +# print l out.close() out2.close() diff --git a/src/disk_io_thread.cpp b/src/disk_io_thread.cpp index 1ecda6f22..3b8ab4043 100644 --- a/src/disk_io_thread.cpp +++ b/src/disk_io_thread.cpp @@ -827,6 +827,9 @@ namespace libtorrent { case disk_io_job::abort_torrent: { +#ifdef TORRENT_DISK_STATS + m_log << log_time() << " abort_torrent " << std::endl; +#endif mutex_t::scoped_lock jl(m_queue_mutex); for (std::list::iterator i = m_jobs.begin(); i != m_jobs.end();) @@ -849,6 +852,9 @@ namespace libtorrent } case disk_io_job::abort_thread: { +#ifdef TORRENT_DISK_STATS + m_log << log_time() << " abort_thread " << std::endl; +#endif mutex_t::scoped_lock jl(m_queue_mutex); m_abort = true; @@ -1114,7 +1120,7 @@ namespace libtorrent case disk_io_job::check_fastresume: { #ifdef TORRENT_DISK_STATS - m_log << log_time() << " check fastresume" << std::endl; + m_log << log_time() << " check_fastresume" << std::endl; #endif lazy_entry const* rd = (lazy_entry const*)j.buffer; TORRENT_ASSERT(rd != 0); @@ -1124,7 +1130,7 @@ namespace libtorrent case disk_io_job::check_files: { #ifdef TORRENT_DISK_STATS - m_log << log_time() << " check files" << std::endl; + m_log << log_time() << " check_files" << std::endl; #endif int piece_size = j.storage->info()->piece_length(); for (int processed = 0; processed < 4 * 1024 * 1024; processed += piece_size) @@ -1160,7 +1166,7 @@ namespace libtorrent case disk_io_job::save_resume_data: { #ifdef TORRENT_DISK_STATS - m_log << log_time() << " save resume data" << std::endl; + m_log << log_time() << " save_resume_data" << std::endl; #endif j.resume_data.reset(new entry(entry::dictionary_t)); j.storage->write_resume_data(*j.resume_data); @@ -1170,7 +1176,7 @@ namespace libtorrent case disk_io_job::rename_file: { #ifdef TORRENT_DISK_STATS - m_log << log_time() << " rename file" << std::endl; + m_log << log_time() << " rename_file" << std::endl; #endif ret = j.storage->rename_file_impl(j.piece, j.str); } diff --git a/src/session_impl.cpp b/src/session_impl.cpp index 374f85b0c..bdba6d506 100644 --- a/src/session_impl.cpp +++ b/src/session_impl.cpp @@ -437,6 +437,9 @@ namespace aux { { mutex_t::scoped_lock l(m_mutex); if (m_paused) return; +#if defined TORRENT_VERBOSE_LOGGING || defined TORRENT_LOGGING + (*m_logger) << time_now_string() << " *** session paused ***\n"; +#endif m_paused = true; for (torrent_map::iterator i = m_torrents.begin() , end(m_torrents.end()); i != end; ++i) @@ -463,7 +466,7 @@ namespace aux { { mutex_t::scoped_lock l(m_mutex); if (m_abort) return; -#if defined(TORRENT_LOGGING) +#if defined TORRENT_LOGGING (*m_logger) << time_now_string() << " *** ABORT CALLED ***\n"; #endif // abort the main thread diff --git a/src/torrent.cpp b/src/torrent.cpp index 8256712f5..d0dc7ae79 100644 --- a/src/torrent.cpp +++ b/src/torrent.cpp @@ -1094,7 +1094,11 @@ namespace libtorrent if (!ae.complete_sent && is_seed()) req.event = tracker_request::completed; } -#if defined(TORRENT_VERBOSE_LOGGING) || defined(TORRENT_LOGGING) +#if defined TORRENT_VERBOSE_LOGGING || defined TORRENT_LOGGING + (*m_ses.m_logger) << time_now_string() << " ==> TACKER REQUEST " << req.url + << " event=" << (req.event==tracker_request::stopped?"stopped" + :req.event==tracker_request::started?"started":"") + << " abort=" << m_abort << "\n"; if (m_abort) { boost::shared_ptr tl(new aux::tracker_logger(m_ses)); @@ -1515,7 +1519,7 @@ namespace libtorrent { session_impl::mutex_t::scoped_lock l(m_ses.m_mutex); -#if defined(TORRENT_VERBOSE_LOGGING) || defined(TORRENT_LOGGING) +#if defined TORRENT_VERBOSE_LOGGING || defined TORRENT_LOGGING (*m_ses.m_logger) << time_now_string() << " *** PIECE_FINISHED [ p: " << index << " chk: " << ((passed_hash_check == 0) ?"passed":passed_hash_check == -1