add new piece picker logging alert category

examples/client_test.cpp

@@ -1563,6 +1563,7 @@ int main(int argc, char* argv[])
 		+ alert::torrent_log_notification
 		+ alert::peer_log_notification
 		+ alert::dht_log_notification
+		+ alert::picker_log_notification
 		));
 
 	libtorrent::session ses(settings);

include/libtorrent/alert.hpp

@@ -200,6 +200,9 @@ namespace libtorrent {
 			// for debugging the UPnP or NAT-PMP implementation
 			port_mapping_log_notification = 0x80000,
 
+			// enables verbose logging from the piece picker.
+			picker_log_notification       = 0x100000,
+
 			// The full bitmask, representing all available categories.
 			//
 			// since the enum is signed, make sure this isn't

include/libtorrent/alert_types.hpp

@@ -72,6 +72,7 @@ namespace libtorrent
 	namespace aux {
 		struct stack_allocator;
 	}
+	struct piece_block;
 
 	// maps an operation id (from peer_error_alert and peer_disconnected_alert)
 	// to its name. See peer_connection for the constants
@@ -2428,6 +2429,61 @@ namespace libtorrent
 		int m_response_size;
 	};
 
+	// this is posted when one or more blocks are picked by the piece picker,
+	// assuming the verbose piece picker logging is enabled (see
+	// picker_log_notification).
+	struct TORRENT_EXPORT picker_log_alert : peer_alert
+	{
+#ifndef TORRENT_DISABLE_LOGGING
+
+		// internal
+		picker_log_alert(aux::stack_allocator& alloc, torrent_handle h
+			, tcp::endpoint const& ep, peer_id const& peer_id, boost::uint32_t flags
+			, piece_block const* blocks, int num_blocks);
+
+		TORRENT_DEFINE_ALERT(picker_log_alert, 89)
+
+		static const int static_category = alert::picker_log_notification;
+		virtual std::string message() const TORRENT_OVERRIDE;
+
+#endif // TORRENT_DISABLE_LOGGING
+
+		enum picker_flags_t
+		{
+			// the ratio of partial pieces is too high. This forces a preference
+			// for picking blocks from partial pieces.
+			partial_ratio          = 0x1,
+			prioritize_partials    = 0x2,
+			rarest_first_partials  = 0x4,
+			rarest_first           = 0x8,
+			reverse_rarest_first   = 0x10,
+			suggested_pieces       = 0x20,
+			prio_sequential_pieces = 0x40,
+			sequential_pieces      = 0x80,
+			reverse_pieces         = 0x100,
+			time_critical          = 0x200,
+			random_pieces          = 0x400,
+			prefer_contiguous      = 0x800,
+			reverse_sequential     = 0x1000,
+			backup1                = 0x2000,
+			backup2                = 0x4000,
+			end_game               = 0x8000
+		};
+
+#ifndef TORRENT_DISABLE_LOGGING
+
+		// this is a bitmask of which features were enabled for this particular
+		// pick. The bits are defined in the picker_flags_t enum.
+		boost::uint32_t picker_flags;
+
+		std::vector<piece_block> blocks() const;
+
+	private:
+		int m_array_idx;
+		int m_num_blocks;
+#endif // TORRENT_DISABLE_LOGGING
+	};
+
 #undef TORRENT_DEFINE_ALERT_IMPL
 #undef TORRENT_DEFINE_ALERT
 #undef TORRENT_DEFINE_ALERT_PRIO

include/libtorrent/piece_picker.hpp

@@ -32,9 +32,6 @@ POSSIBILITY OF SUCH DAMAGE.
 #ifndef TORRENT_PIECE_PICKER_HPP_INCLUDED
 #define TORRENT_PIECE_PICKER_HPP_INCLUDED
 
-// this is really only useful for debugging unit tests
-//#define TORRENT_PICKER_LOG
-
 // heavy weight reference counting invariant checks
 //#define TORRENT_DEBUG_REFCOUNTS
 
@@ -293,7 +290,7 @@ namespace libtorrent
 		// this feature is used by web_peer_connection to request larger blocks
 		// at a time to mitigate limited pipelining and lack of keep-alive
 		// (i.e. higher overhead per request).
-		void pick_pieces(bitfield const& pieces
+		boost::uint32_t pick_pieces(bitfield const& pieces
 			, std::vector<piece_block>& interesting_blocks, int num_blocks
 			, int prefer_contiguous_blocks, torrent_peer* peer
 			, int options, std::vector<int> const& suggested_pieces
@@ -450,9 +447,6 @@ namespace libtorrent
 		void check_peer_invariant(bitfield const& have, torrent_peer const* p) const;
 		void check_invariant(const torrent* t = 0) const;
 #endif
-#if defined TORRENT_PICKER_LOG || defined TORRENT_DEBUG
-		void print_pieces() const;
-#endif
 
 		// functor that compares indices on downloading_pieces
 		struct has_index
@@ -488,6 +482,10 @@ namespace libtorrent
 		std::pair<int, int> expand_piece(int piece, int whole_pieces
 			, bitfield const& have, int options) const;
 
+		// only defined when TORRENT_PICKER_LOG is defined, used for debugging
+		// unit tests
+		void print_pieces() const;
+
 		struct piece_pos
 		{
 			piece_pos() {}

src/alert.cpp

@@ -44,6 +44,7 @@ POSSIBILITY OF SUCH DAMAGE.
 #include "libtorrent/aux_/time.hpp"
 #include "libtorrent/performance_counters.hpp"
 #include "libtorrent/stack_allocator.hpp"
+#include "libtorrent/piece_picker.hpp" // for piece_block
 
 #include "libtorrent/aux_/escape_string.hpp" // for convert_from_native
 
@@ -1887,5 +1888,78 @@ namespace libtorrent {
 		return ret;
 	}
 
+#ifndef TORRENT_DISABLE_LOGGING
+
+	picker_log_alert::picker_log_alert(aux::stack_allocator& alloc, torrent_handle h
+		, tcp::endpoint const& ep, peer_id const& peer_id, boost::uint32_t flags
+		, piece_block const* blocks, int num_blocks)
+		: peer_alert(alloc, h, ep, peer_id)
+		, picker_flags(flags)
+		, m_array_idx(alloc.copy_buffer(reinterpret_cast<char const*>(blocks)
+			, num_blocks * sizeof(piece_block)))
+		, m_num_blocks(num_blocks)
+	{}
+
+	std::vector<piece_block> picker_log_alert::blocks() const
+	{
+		// we need to copy this array to make sure the structures are properly
+		// aigned, not just to have a nice API
+		std::vector<piece_block> ret;
+		ret.resize(m_num_blocks);
+
+		char const* start = m_alloc.ptr(m_array_idx);
+		memcpy(&ret[0], start, m_num_blocks * sizeof(piece_block));
+
+		return ret;
+	}
+
+	std::string picker_log_alert::message() const
+	{
+		static char const* const flag_names[] =
+		{
+			"partial_ratio ",
+			"prioritize_partials ",
+			"rarest_first_partials ",
+			"rarest_first ",
+			"reverse_rarest_first ",
+			"suggested_pieces ",
+			"prio_sequential_pieces ",
+			"sequential_pieces ",
+			"reverse_pieces ",
+			"time_critical ",
+			"random_pieces ",
+			"prefer_contiguous ",
+			"reverse_sequential ",
+			"backup1 ",
+			"backup2 ",
+			"end_game "
+		};
+
+		std::string ret = peer_alert::message();
+
+		boost::uint32_t flags = picker_flags;
+		int idx = 0;
+		ret += " picker_log [ ";
+		for (; flags != 0; flags >>= 1, ++idx)
+		{
+			if ((flags & 1) == 0) continue;
+			ret += flag_names[idx];
+		}
+		ret += "] ";
+
+		std::vector<piece_block> b = blocks();
+
+		for (int i = 0; i < int(b.size()); ++i)
+		{
+			char buf[50];
+			snprintf(buf, sizeof(buf), "(%d,%d) "
+				, b[i].piece_index, b[i].block_index);
+			ret += buf;
+		}
+		return ret;
+	}
+
+#endif // TORRENT_DISABLE_LOGGING
+
 } // namespace libtorrent
 

src/piece_picker.cpp

@@ -48,6 +48,7 @@ POSSIBILITY OF SUCH DAMAGE.
 #include "libtorrent/random.hpp"
 #include "libtorrent/alloca.hpp"
 #include "libtorrent/performance_counters.hpp" // for counters
+#include "libtorrent/alert_types.hpp" // for picker_log_alert
 
 #if TORRENT_USE_ASSERTS
 #include "libtorrent/peer_connection.hpp"
@@ -65,6 +66,9 @@ POSSIBILITY OF SUCH DAMAGE.
 //#define TORRENT_NO_EXPENSIVE_INVARIANT_CHECK
 //#define TORRENT_PIECE_PICKER_INVARIANT_CHECK
 
+// this is really only useful for debugging unit tests
+//#define TORRENT_PICKER_LOG
+
 namespace libtorrent
 {
 
@@ -392,7 +396,7 @@ namespace libtorrent
 		}
 	}
 
-#if defined TORRENT_PICKER_LOG || defined TORRENT_DEBUG
+#if defined TORRENT_PICKER_LOG
 	void piece_picker::print_pieces() const
 	{
 		int limit = 20;
@@ -431,7 +435,7 @@ namespace libtorrent
 		}
 		std::cerr << std::endl;
 	}
-#endif // TORRENT_PIECE_PICKER
+#endif // TORRENT_PICKER_LOG
 #endif // TORRENT_USE_INVARIANT_CHECKS
 
 #if TORRENT_USE_INVARIANT_CHECKS
@@ -892,10 +896,6 @@ namespace libtorrent
 
 #ifdef TORRENT_PICKER_LOG
 			print_pieces();
-#endif
-//			shuffle(priority, new_index);
-#ifdef TORRENT_PICKER_LOG
-//			print_pieces();
 #endif
 		}
 	}
@@ -1957,7 +1957,10 @@ namespace libtorrent
 
 	// only one of rarest_first or sequential can be set
 
-	void piece_picker::pick_pieces(bitfield const& pieces
+	// the return value is a combination of picker_log_alert::picker_flags_t,
+	// indicating which path throught the picker we took to arrive at the
+	// returned block picks.
+	boost::uint32_t piece_picker::pick_pieces(bitfield const& pieces
 		, std::vector<piece_block>& interesting_blocks, int num_blocks
 		, int prefer_contiguous_blocks, torrent_peer* peer
 		, int options, std::vector<int> const& suggested_pieces
@@ -1966,6 +1969,7 @@ namespace libtorrent
 		) const
 	{
 		TORRENT_ASSERT(peer == 0 || peer->in_use);
+		boost::uint32_t ret = 0;
 
 		// prevent the number of partial pieces to grow indefinitely
 		// make this scale by the number of peers we have. For large
@@ -1986,8 +1990,12 @@ namespace libtorrent
 			// prefer whole pieces (otherwise partial pieces would be de-prioritized)
 			options |= prioritize_partials;
 			prefer_contiguous_blocks = 0;
+
+			ret |= picker_log_alert::partial_ratio;
 		}
 
+		if (prefer_contiguous_blocks) ret |= picker_log_alert::prefer_contiguous;
+
 		// only one of rarest_first and sequential can be set.
 		TORRENT_ASSERT(((options & rarest_first) ? 1 : 0)
 			+ ((options & sequential) ? 1 : 0) <= 1);
@@ -1997,8 +2005,7 @@ namespace libtorrent
 		TORRENT_ASSERT(num_blocks > 0);
 		TORRENT_ASSERT(pieces.size() == m_piece_map.size());
 
-		TORRENT_ASSERT(!m_priority_boundries.empty()
+		TORRENT_ASSERT(!m_priority_boundries.empty() || m_dirty);
-			|| m_dirty);
 
 		// this will be filled with blocks that we should not request
 		// unless we can't find num_blocks among the other ones.
@@ -2049,6 +2056,8 @@ namespace libtorrent
 			// now, sort the list.
 			if (options & rarest_first)
 			{
+				ret |= picker_log_alert::rarest_first_partials;
+
 				// TODO: this could probably be optimized by incrementally
 				// calling partial_sort to sort one more element in the list. Because
 				// chances are that we'll just need a single piece, and once we've
@@ -2061,10 +2070,12 @@ namespace libtorrent
 
 			for (int i = 0; i < num_ordered_partials; ++i)
 			{
+				ret |= picker_log_alert::prioritize_partials;
+
 				num_blocks = add_blocks_downloading(*ordered_partials[i], pieces
 					, interesting_blocks, backup_blocks, backup_blocks2
 					, num_blocks, prefer_contiguous_blocks, peer, options);
-				if (num_blocks <= 0) return;
+				if (num_blocks <= 0) return ret;
 				if (int(backup_blocks.size()) >= num_blocks
 					&& int(backup_blocks2.size()) >= num_blocks)
 					break;
@@ -2072,11 +2083,11 @@ namespace libtorrent
 
 			num_blocks = append_blocks(interesting_blocks, backup_blocks
 				, num_blocks);
-			if (num_blocks <= 0) return;
+			if (num_blocks <= 0) return ret;
 
 			num_blocks = append_blocks(interesting_blocks, backup_blocks2
 				, num_blocks);
-			if (num_blocks <= 0) return;
+			if (num_blocks <= 0) return ret;
 		}
 
 		if (!suggested_pieces.empty())
@@ -2091,12 +2102,15 @@ namespace libtorrent
 
 				pc.inc_stats_counter(counters::piece_picker_suggest_loops);
 				if (!is_piece_free(*i, pieces)) continue;
+
+				ret |= picker_log_alert::suggested_pieces;
+
 				num_blocks = add_blocks(*i, pieces
 					, interesting_blocks, backup_blocks
 					, backup_blocks2, num_blocks
 					, prefer_contiguous_blocks, peer, empty_vector
 					, options);
-				if (num_blocks <= 0) return;
+				if (num_blocks <= 0) return ret;
 			}
 		}
 
@@ -2109,12 +2123,15 @@ namespace libtorrent
 				i != m_pieces.end() && piece_priority(*i) == priority_levels - 1; ++i)
 			{
 				if (!is_piece_free(*i, pieces)) continue;
+
+				ret |= picker_log_alert::prio_sequential_pieces;
+
 				num_blocks = add_blocks(*i, pieces
 					, interesting_blocks, backup_blocks
 					, backup_blocks2, num_blocks
 					, prefer_contiguous_blocks, peer, suggested_pieces
 					, options);
-				if (num_blocks <= 0) return;
+				if (num_blocks <= 0) return ret;
 			}
 
 			// in time critical mode, only pick high priority pieces
@@ -2128,12 +2145,15 @@ namespace libtorrent
 						if (!is_piece_free(i, pieces)) continue;
 						// we've already added high priority pieces
 						if (piece_priority(i) == priority_levels - 1) continue;
+
+						ret |= picker_log_alert::reverse_sequential;
+
 						num_blocks = add_blocks(i, pieces
 							, interesting_blocks, backup_blocks
 							, backup_blocks2, num_blocks
 							, prefer_contiguous_blocks, peer, suggested_pieces
 							, options);
-						if (num_blocks <= 0) return;
+						if (num_blocks <= 0) return ret;
 					}
 				}
 				else
@@ -2144,12 +2164,15 @@ namespace libtorrent
 						if (!is_piece_free(i, pieces)) continue;
 						// we've already added high priority pieces
 						if (piece_priority(i) == priority_levels - 1) continue;
+
+						ret |= picker_log_alert::sequential_pieces;
+
 						num_blocks = add_blocks(i, pieces
 							, interesting_blocks, backup_blocks
 							, backup_blocks2, num_blocks
 							, prefer_contiguous_blocks, peer, suggested_pieces
 							, options);
-						if (num_blocks <= 0) return;
+						if (num_blocks <= 0) return ret;
 					}
 				}
 			}
@@ -2174,12 +2197,15 @@ namespace libtorrent
 						pc.inc_stats_counter(counters::piece_picker_reverse_rare_loops);
 
 						if (!is_piece_free(m_pieces[p], pieces)) continue;
+
+						ret |= picker_log_alert::reverse_rarest_first;
+
 						num_blocks = add_blocks(m_pieces[p], pieces
 							, interesting_blocks, backup_blocks
 							, backup_blocks2, num_blocks
 							, prefer_contiguous_blocks, peer, suggested_pieces
 							, options);
-						if (num_blocks <= 0) return;
+						if (num_blocks <= 0) return ret;
 					}
 				}
 			}
@@ -2200,12 +2226,14 @@ namespace libtorrent
 
 					if (!is_piece_free(*i, pieces)) continue;
 
+					ret |= picker_log_alert::rarest_first;
+
 					num_blocks = add_blocks(*i, pieces
 						, interesting_blocks, backup_blocks
 						, backup_blocks2, num_blocks
 						, prefer_contiguous_blocks, peer, suggested_pieces
 						, options);
-					if (num_blocks <= 0) return;
+					if (num_blocks <= 0) return ret;
 				}
 			}
 		}
@@ -2217,12 +2245,15 @@ namespace libtorrent
 				i != m_pieces.end() && piece_priority(*i) == priority_levels - 1; ++i)
 			{
 				if (!is_piece_free(*i, pieces)) continue;
+
+				ret |= picker_log_alert::time_critical;
+
 				num_blocks = add_blocks(*i, pieces
 					, interesting_blocks, backup_blocks
 					, backup_blocks2, num_blocks
 					, prefer_contiguous_blocks, peer, suggested_pieces
 					, options);
-				if (num_blocks <= 0) return;
+				if (num_blocks <= 0) return ret;
 			}
 		}
 		else
@@ -2263,6 +2294,9 @@ namespace libtorrent
 						TORRENT_ASSERT(m_piece_map[k].downloading() == false);
 						TORRENT_ASSERT(m_piece_map[k].priority(this) >= 0);
 						const int num_blocks_in_piece = blocks_in_piece(k);
+
+						ret |= picker_log_alert::random_pieces;
+
 						for (int j = 0; j < num_blocks_in_piece; ++j)
 						{
 							pc.inc_stats_counter(counters::piece_picker_rand_loops);
@@ -2278,6 +2312,8 @@ namespace libtorrent
 				}
 				else
 				{
+					ret |= picker_log_alert::random_pieces;
+
 					num_blocks = add_blocks(piece, pieces
 						, interesting_blocks, backup_blocks
 						, backup_blocks2, num_blocks
@@ -2293,7 +2329,7 @@ namespace libtorrent
 		}
 get_out:
 
-		if (num_blocks <= 0) return;
+		if (num_blocks <= 0) return ret;
 
 #if TORRENT_USE_INVARIANT_CHECKS
 		verify_pick(interesting_blocks, pieces);
@@ -2301,17 +2337,19 @@ get_out:
 		verify_pick(backup_blocks2, pieces);
 #endif
 
+		ret |= picker_log_alert::backup1;
 		num_blocks = append_blocks(interesting_blocks, backup_blocks
 			, num_blocks);
-		if (num_blocks <= 0) return;
+		if (num_blocks <= 0) return ret;
 
+		ret |= picker_log_alert::backup2;
 		num_blocks = append_blocks(interesting_blocks, backup_blocks2, num_blocks);
-		if (num_blocks <= 0) return;
+		if (num_blocks <= 0) return ret;
 
 		// ===== THIS IS FOR END-GAME MODE =====
 
 		// don't double-pick anything if the peer is on parole
-		if (options & on_parole) return;
+		if (options & on_parole) return ret;
 
 		// in end game mode we pick a single block
 		// that has already been requested from someone
@@ -2330,7 +2368,7 @@ get_out:
 		int partials_size = (std::min)(200, int(
 				m_downloads[piece_pos::piece_downloading].size()
 			+ m_downloads[piece_pos::piece_full].size()));
-		if (partials_size == 0) return;
+		if (partials_size == 0) return ret;
 
 		downloading_piece const** partials
 			= TORRENT_ALLOCA(downloading_piece const*, partials_size);
@@ -2426,6 +2464,8 @@ get_out:
 			// are we done?
 			if (!temp.empty())
 			{
+				ret |= picker_log_alert::end_game;
+
 				interesting_blocks.push_back(temp[random() % temp.size()]);
 				--num_blocks;
 				break;
@@ -2489,7 +2529,6 @@ get_out:
 
 		if (interesting_blocks.empty())
 		{
-//			print_pieces();
 			for (int i = 0; i < num_pieces(); ++i)
 			{
 				if (!pieces[i]) continue;
@@ -2503,23 +2542,10 @@ get_out:
 
 				TORRENT_ASSERT(k != m_downloads[download_state].end());
 				if (k == m_downloads[download_state].end()) continue;
-
-				// this assert is not valid for web_seeds
-				/*
-				const int num_blocks_in_piece = blocks_in_piece(k->index);
-				block_info const* binfo = blocks_for_piece(*k);
-				for (int j = 0; j < num_blocks_in_piece; ++j)
-				{
-					block_info const& info = binfo[j];
-					TORRENT_ASSERT(info.piece_index == k->index);
-					if (info.state == block_info::state_finished) continue;
-					TORRENT_ASSERT(info.peer != 0);
-				}
-				*/
 			}
 		}
-#endif
+#endif // TORRENT_DEBUG && !defined TORRENT_DISABLE_INVARIANT_CHECKS
-
+		return ret;
 	}
 
 	// have piece means that the piece passed hash check

src/request_blocks.cpp

@@ -37,6 +37,7 @@ POSSIBILITY OF SUCH DAMAGE.
 #include "libtorrent/peer_info.hpp" // for peer_info flags
 #include "libtorrent/performance_counters.hpp" // for counters
 #include "libtorrent/request_blocks.hpp"
+#include "libtorrent/alert_manager.hpp"
 
 #include <vector>
 
@@ -155,15 +156,23 @@ namespace libtorrent
 		// the last argument is if we should prefer whole pieces
 		// for this peer. If we're downloading one piece in 20 seconds
 		// then use this mode.
-		p.pick_pieces(*bits, interesting_pieces
+		boost::uint32_t flags = p.pick_pieces(*bits, interesting_pieces
 			, num_requests, prefer_contiguous_blocks, c.peer_info_struct()
 			, c.picker_options(), suggested, t.num_peers()
 			, ses.stats_counters());
 
 #ifndef TORRENT_DISABLE_LOGGING
+		if (t.alerts().should_post<picker_log_alert>()
+			&& !interesting_pieces.empty())
+		{
+			t.alerts().emplace_alert<picker_log_alert>(t.get_handle(), c.remote()
+				, c.pid(), flags, &interesting_pieces[0], int(interesting_pieces.size()));
+		}
 		c.peer_log(peer_log_alert::info, "PIECE_PICKER"
 			, "prefer_contiguous: %d picked: %d"
 			, prefer_contiguous_blocks, int(interesting_pieces.size()));
+#else
+		TORRENT_UNUSED(flags);
 #endif
 
 		// if the number of pieces we have + the number of pieces

test/settings.cpp

@@ -41,7 +41,8 @@ libtorrent::settings_pack settings()
 	const int mask = alert::all_categories
 		& ~(alert::progress_notification
 			| alert::performance_warning
-			| alert::stats_notification);
+			| alert::stats_notification
+			| alert::picker_log_notification);
 
 	settings_pack pack;
 	pack.set_bool(settings_pack::enable_lsd, false);