added some session logging. added more disk-io-thread stats logging and parse script

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()
 

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<disk_io_job>::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);
 				}

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

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<aux::tracker_logger> 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