Merge lp:~widelands-dev/widelands/bug-1678987-save-handler into lp:widelands

[GunChleoc]

Fix performance problems with long savegames

- The savehandler now calculates the next interval after a save has finished.
  This fixes endless autosave cycles when a save takes longer than the
  interval.

- When saving the Player Info Packet, only save ware statistics that the
  player's tribe owns

- Save ware statistics as strings to reduce the number of hard drive write
  operations by an order of magnitude for long games

The savehandler now calculates the next interval after a save has finished. This fixes endless autosave cycles when a save takes longer than the interval.

Also, when saving the Player Info Packet, only save ware statistics that the player's tribe owns.

Writing the Player Info Packet is still very slow in the savegame attached to this branch, I want to do some further improvements before we merge this.

DO NOT MERGE TRUNK into this branch yet, as it will make the sample savegame incompatible.

[bunnybot (widelandsofficial)]

Continuous integration builds have changed state:

Travis build 3647. State: passed. Details: https://travis-ci.org/widelands/widelands/builds/401473258.
Appveyor build 3446. State: success. Details: https://ci.appveyor.com/project/widelands-dev/widelands/build/_widelands_dev_widelands_bug_1678987_save_handler-3446.

[bunnybot (widelandsofficial)]

Continuous integration builds have changed state:

Travis build 3647. State: passed. Details: https://travis-ci.org/widelands/widelands/builds/401473258.
Appveyor build 3446. State: success. Details: https://ci.appveyor.com/project/widelands-dev/widelands/build/_widelands_dev_widelands_bug_1678987_save_handler-3446.

[GunChleoc (gunchleoc)]

This is ready now.

Stats for the attached savegame on my machine:

Before r8741:
Game: Writing Player Info ... took 141029ms

After:
Game: Writing Player Info ... took 30962ms

[Klaus Halfmann (klaus-halfmann)]

Wow, that speedup is impressive but you write:
> When saving the Player Info Packet, only save ware statistics that the player's tribe owns

So When I switch the tribe after saving I will have no statistic?
And the AI statistics will be completely lost?

Must check this if this is worth the speedup.

[Klaus Halfmann (klaus-halfmann)]

Review is ok for me:
 * more const is never wrong
 * Did not grasp that string thing, though.

Will compile and testplay this now, perhaps fo my next youtube video?

[Klaus Halfmann (klaus-halfmann)]

Playtestet this now this now for perhpas an hour:
 * Saving is noticable faster!
 * Found String like: 0^@gold_ore^@^@^@^@^@0|0|0|0|0|0|0 ... empire_bread^@^@^@^@^@... |1|1|1|2|2|2|1|1|1|1|1|0|1|1|0|1|2|0|2|0

Gun: is OK for me, you may want to care for some of my inline commentsm

review: Approve (reiew, compile testplay.)

[GunChleoc (gunchleoc)]

I have replied to some comments.

I have had an idea for more streamlining, so there will be an additional commit to this branch.

[Klaus Halfmann (klaus-halfmann)]

Playing in an AI slot gave me mixed results:
 * One one slot the ware statistics wherer complete.
 * with the next slot the statistics just started again after the save.

I assume the AI does neither need nor rely on these statistics?
If this is intenden we should at lest warn the user when loading a game.

Please confirm.

review: Needs Information

[GunChleoc (gunchleoc)]

These stats are only used to show them to the player in-game (the ware statistics menus with the graphs in them). The AI doesn't care about them at all.

=== modified file 'src/game_io/game_player_info_packet.cc'
--- src/game_io/game_player_info_packet.cc	2018-04-28 07:02:42 +0000
+++ src/game_io/game_player_info_packet.cc	2018-07-13 13:41:35 +0000
@@ -30,7 +30,7 @@
 
 namespace Widelands {
 
-constexpr uint16_t kCurrentPacketVersion = 21;
+constexpr uint16_t kCurrentPacketVersion = 22;
 
 void GamePlayerInfoPacket::read(FileSystem& fs, Game& game, MapObjectLoader*) {
 	try {
@@ -59,7 +59,7 @@
 					player->set_see_all(see_all);
 
 					player->set_ai(fr.c_string());
-					player->read_statistics(fr);
+					player->read_statistics(fr, packet_version);
 					player->read_remaining_shipnames(fr, packet_version);
 
 					player->casualties_ = fr.unsigned_32();

=== modified file 'src/logic/player.cc'
--- src/logic/player.cc	2018-07-12 04:41:20 +0000
+++ src/logic/player.cc	2018-07-13 13:41:35 +0000
@@ -22,6 +22,7 @@
 #include <cassert>
 #include <memory>
 
+#include <boost/algorithm/string.hpp>
 #include <boost/bind.hpp>
 #include <boost/format.hpp>
 #include <boost/signals2.hpp>
@@ -1357,25 +1358,45 @@
  *
  * \param fr source stream
  */
-void Player::read_statistics(FileRead& fr) {
+void Player::read_statistics(FileRead& fr, const uint16_t packet_version) {
 	uint16_t nr_wares = fr.unsigned_16();
-	uint16_t nr_entries = fr.unsigned_16();
+	size_t nr_entries = fr.unsigned_16();
+
+	// Stats are saved as a single string to reduce number of hard disk write operations
+	const auto parse_stats = [nr_entries](std::vector<std::vector<uint32_t>>* stats, const DescriptionIndex ware_index, const std::string& stats_string, const std::string& description) {
+		if (!stats_string.empty()) {
+			std::vector<std::string> stats_vector;
+			boost::split(stats_vector, stats_string, boost::is_any_of("|"));
+			if (stats_vector.size() != nr_entries) {
+				throw GameDataError("wrong number of %s statistics - expected %" PRIuS " but got %" PRIuS, description.c_str(), nr_entries, stats_vector.size());
+			}
+			for (size_t j = 0; j < nr_entries; ++j) {
+				stats->at(ware_index)[j] = static_cast<unsigned int>(atoi(stats_vector.at(j).c_str()));
+			}
+		} else if (nr_entries > 0) {
+			throw GameDataError("wrong number of %s statistics - expected %" PRIuS " but got 0", description.c_str(), nr_entries);
+		}
+	};
 
 	for (uint32_t i = 0; i < current_produced_statistics_.size(); ++i)
 		ware_productions_[i].resize(nr_entries);
 
 	for (uint16_t i = 0; i < nr_wares; ++i) {
-		std::string name = fr.c_string();
-		DescriptionIndex idx = egbase().tribes().ware_index(name);
+		const std::string name = fr.c_string();
+		const DescriptionIndex idx = egbase().tribes().ware_index(name);
 		if (!egbase().tribes().ware_exists(idx)) {
 			log("Player %u statistics: unknown ware name %s", player_number(), name.c_str());
 			continue;
 		}
 
 		current_produced_statistics_[idx] = fr.unsigned_32();
-
-		for (uint32_t j = 0; j < nr_entries; ++j)
-			ware_productions_[idx][j] = fr.unsigned_32();
+		if (packet_version < 22) {
+			for (uint32_t j = 0; j < nr_entries; ++j) {
+				ware_productions_[idx][j] = fr.unsigned_32();
+			}
+		} else {
+			parse_stats(&ware_productions_, idx, fr.c_string(), "produced");
+		}
 	}
 
 	// Read consumption statistics
@@ -1386,8 +1407,8 @@
 		ware_consumptions_[i].resize(nr_entries);
 
 	for (uint16_t i = 0; i < nr_wares; ++i) {
-		std::string name = fr.c_string();
-		DescriptionIndex idx = egbase().tribes().ware_index(name);
+		const std::string name = fr.c_string();
+		const DescriptionIndex idx = egbase().tribes().ware_index(name);
 		if (!egbase().tribes().ware_exists(idx)) {
 			log("Player %u consumption statistics: unknown ware name %s", player_number(),
 			    name.c_str());
@@ -1395,9 +1416,14 @@
 		}
 
 		current_consumed_statistics_[idx] = fr.unsigned_32();
-
-		for (uint32_t j = 0; j < nr_entries; ++j)
-			ware_consumptions_[idx][j] = fr.unsigned_32();
+		// TODO(GunChleoc): Get rid of this savegame compatibility code after build 21
+		if (packet_version < 22) {
+			for (uint32_t j = 0; j < nr_entries; ++j) {
+				ware_consumptions_[idx][j] = fr.unsigned_32();
+			}
+		} else {
+			parse_stats(&ware_consumptions_, idx, fr.c_string(), "consumed");
+		}
 	}
 
 	// Read stock statistics
@@ -1408,15 +1434,20 @@
 		ware_stocks_[i].resize(nr_entries);
 
 	for (uint16_t i = 0; i < nr_wares; ++i) {
-		std::string name = fr.c_string();
-		DescriptionIndex idx = egbase().tribes().ware_index(name);
+		const std::string name = fr.c_string();
+		const DescriptionIndex idx = egbase().tribes().ware_index(name);
 		if (!egbase().tribes().ware_exists(idx)) {
 			log("Player %u stock statistics: unknown ware name %s", player_number(), name.c_str());
 			continue;
 		}
 
-		for (uint32_t j = 0; j < nr_entries; ++j)
-			ware_stocks_[idx][j] = fr.unsigned_32();
+		if (packet_version < 22) {
+			for (uint32_t j = 0; j < nr_entries; ++j) {
+				ware_stocks_[idx][j] = fr.unsigned_32();
+			}
+		} else {
+			parse_stats(&ware_stocks_, idx, fr.c_string(), "stock");
+		}
 	}
 
 	// All statistics should have the same size
@@ -1439,39 +1470,52 @@
 }
 
 /**
- * Write statistics data to the give file
+ * Write statistics data to the given file
  */
 void Player::write_statistics(FileWrite& fw) const {
+	// Save stats as a single string to reduce number of hard disk write operations
+	const auto write_stats = [&fw](const std::vector<std::vector<uint32_t>>& stats, const DescriptionIndex ware_index) {
+		std::ostringstream oss("");
+		if (!stats[ware_index].empty()) {
+			for (uint32_t i = 0; i < stats[ware_index].size() - 1; ++i) {
+				oss << stats[ware_index][i] << "|";
+			}
+			oss << stats[ware_index][stats[ware_index].size() - 1];
+		}
+		fw.c_string(oss.str());
+	};
+
+	const Tribes& tribes = egbase().tribes();
+	const std::set<DescriptionIndex>& tribe_wares = tribe().wares();
+	const size_t nr_wares = tribe_wares.size();
+
 	// Write produce statistics
-	fw.unsigned_16(current_produced_statistics_.size());
+	fw.unsigned_16(nr_wares);
 	fw.unsigned_16(ware_productions_[0].size());
 
-	for (uint8_t i = 0; i < current_produced_statistics_.size(); ++i) {
-		fw.c_string(egbase().tribes().get_ware_descr(i)->name());
-		fw.unsigned_32(current_produced_statistics_[i]);
-		for (uint32_t j = 0; j < ware_productions_[i].size(); ++j)
-			fw.unsigned_32(ware_productions_[i][j]);
+	for (const DescriptionIndex ware_index : tribe_wares) {
+		fw.c_string(tribes.get_ware_descr(ware_index)->name());
+		fw.unsigned_32(current_produced_statistics_[ware_index]);
+		write_stats(ware_productions_, ware_index);
 	}
 
 	// Write consume statistics
-	fw.unsigned_16(current_consumed_statistics_.size());
+	fw.unsigned_16(nr_wares);
 	fw.unsigned_16(ware_consumptions_[0].size());
 
-	for (uint8_t i = 0; i < current_consumed_statistics_.size(); ++i) {
-		fw.c_string(egbase().tribes().get_ware_descr(i)->name());
-		fw.unsigned_32(current_consumed_statistics_[i]);
-		for (uint32_t j = 0; j < ware_consumptions_[i].size(); ++j)
-			fw.unsigned_32(ware_consumptions_[i][j]);
+	for (const DescriptionIndex ware_index : tribe_wares) {
+		fw.c_string(tribes.get_ware_descr(ware_index)->name());
+		fw.unsigned_32(current_consumed_statistics_[ware_index]);
+		write_stats(ware_consumptions_, ware_index);
 	}
 
 	// Write stock statistics
-	fw.unsigned_16(ware_stocks_.size());
+	fw.unsigned_16(nr_wares);
 	fw.unsigned_16(ware_stocks_[0].size());
 
-	for (uint8_t i = 0; i < ware_stocks_.size(); ++i) {
-		fw.c_string(egbase().tribes().get_ware_descr(i)->name());
-		for (uint32_t j = 0; j < ware_stocks_[i].size(); ++j)
-			fw.unsigned_32(ware_stocks_[i][j]);
+	for (const DescriptionIndex ware_index : tribe_wares) {
+		fw.c_string(tribes.get_ware_descr(ware_index)->name());
+		write_stats(ware_stocks_, ware_index);
 	}
 }
 }

=== modified file 'src/logic/player.h'
--- src/logic/player.h	2018-07-12 04:41:20 +0000
+++ src/logic/player.h	2018-07-13 13:41:35 +0000
@@ -579,7 +579,7 @@
 
 	std::vector<uint32_t> const* get_ware_stock_statistics(DescriptionIndex const) const;
 
-	void read_statistics(FileRead&);
+	void read_statistics(FileRead&, uint16_t packet_version);
 	void write_statistics(FileWrite&) const;
 	void read_remaining_shipnames(FileRead&, uint16_t packet_version);
 	void write_remaining_shipnames(FileWrite&) const;

=== modified file 'src/logic/save_handler.cc'
--- src/logic/save_handler.cc	2018-04-07 16:59:00 +0000
+++ src/logic/save_handler.cc	2018-07-13 13:41:35 +0000
@@ -83,14 +83,11 @@
  * @return true if game should be saved ad next think().
  */
 bool SaveHandler::check_next_tick(Widelands::Game& game, uint32_t realtime) {
-
 	// Perhaps save is due now?
 	if (autosave_interval_in_ms_ <= 0 || next_save_realtime_ > realtime) {
 		return false;  // no autosave or not due, yet
 	}
 
-	next_save_realtime_ = realtime + autosave_interval_in_ms_;
-
 	// check if game is paused (in any way)
 	if (game.game_controller()->is_paused_or_zero_speed()) {
 		return false;
@@ -125,11 +122,16 @@
 			g_fs->fs_rename(backup_filename, complete_filename);
 		}
 		// Wait 30 seconds until next save try
-		next_save_realtime_ += 30000;
+		next_save_realtime_ = SDL_GetTicks() + 30000;
 	} else {
 		// if backup file was created, time to remove it
-		if (backup_filename.length() > 0 && g_fs->file_exists(backup_filename))
+		if (backup_filename.length() > 0 && g_fs->file_exists(backup_filename)) {
 			g_fs->fs_unlink(backup_filename);
+		}
+
+		// Count save interval from end of save.
+		// This prevents us from going into endless autosave cycles if the save should take longer than the autosave interval.
+		next_save_realtime_ = SDL_GetTicks() + autosave_interval_in_ms_;
 	}
 	return result;
 }
@@ -138,12 +140,11 @@
  * Check if autosave is needed and allowed or save was requested by user.
  */
 void SaveHandler::think(Widelands::Game& game) {
-
 	if (!allow_saving_ || game.is_replay()) {
 		return;
 	}
 
-	uint32_t realtime = SDL_GetTicks();
+	const uint32_t realtime = SDL_GetTicks();
 	initialize(realtime);
 
 	// Are we saving now?
@@ -185,7 +186,6 @@
 		log("Autosave: save took %d ms\n", SDL_GetTicks() - realtime);
 		game.get_ibase()->log_message(_("Game saved"));
 		saving_next_tick_ = false;
-
 	} else {
 		saving_next_tick_ = check_next_tick(game, realtime);
 	}