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

Proposed by GunChleoc on 2018-07-08
Status: Merged
Merged at revision: 8755
Proposed branch: lp:~widelands-dev/widelands/bug-1678987-save-handler
Merge into: lp:widelands
Diff against target: 284 lines (+89/-45)
4 files modified
src/game_io/game_player_info_packet.cc (+2/-2)
src/logic/player.cc (+78/-34)
src/logic/player.h (+1/-1)
src/logic/save_handler.cc (+8/-8)
To merge this branch: bzr merge lp:~widelands-dev/widelands/bug-1678987-save-handler
Reviewer Review Type Date Requested Status
Klaus Halfmann 2018-07-08 Needs Information on 2018-07-14
Review via email: mp+349096@code.launchpad.net

Commit message

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

Description of the change

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.

To post a comment you must log in.
bunnybot (widelandsofficial) wrote :

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) wrote :

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.

8741. By GunChleoc on 2018-07-13

Reduce harddrive access when writing ware statistics to player info.

GunChleoc (gunchleoc) wrote :

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) wrote :

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) wrote :

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) wrote :

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) wrote :

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) wrote :

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) wrote :

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.

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'src/game_io/game_player_info_packet.cc'
2--- src/game_io/game_player_info_packet.cc 2018-04-28 07:02:42 +0000
3+++ src/game_io/game_player_info_packet.cc 2018-07-13 13:41:35 +0000
4@@ -30,7 +30,7 @@
5
6 namespace Widelands {
7
8-constexpr uint16_t kCurrentPacketVersion = 21;
9+constexpr uint16_t kCurrentPacketVersion = 22;
10
11 void GamePlayerInfoPacket::read(FileSystem& fs, Game& game, MapObjectLoader*) {
12 try {
13@@ -59,7 +59,7 @@
14 player->set_see_all(see_all);
15
16 player->set_ai(fr.c_string());
17- player->read_statistics(fr);
18+ player->read_statistics(fr, packet_version);
19 player->read_remaining_shipnames(fr, packet_version);
20
21 player->casualties_ = fr.unsigned_32();
22
23=== modified file 'src/logic/player.cc'
24--- src/logic/player.cc 2018-07-12 04:41:20 +0000
25+++ src/logic/player.cc 2018-07-13 13:41:35 +0000
26@@ -22,6 +22,7 @@
27 #include <cassert>
28 #include <memory>
29
30+#include <boost/algorithm/string.hpp>
31 #include <boost/bind.hpp>
32 #include <boost/format.hpp>
33 #include <boost/signals2.hpp>
34@@ -1357,25 +1358,45 @@
35 *
36 * \param fr source stream
37 */
38-void Player::read_statistics(FileRead& fr) {
39+void Player::read_statistics(FileRead& fr, const uint16_t packet_version) {
40 uint16_t nr_wares = fr.unsigned_16();
41- uint16_t nr_entries = fr.unsigned_16();
42+ size_t nr_entries = fr.unsigned_16();
43+
44+ // Stats are saved as a single string to reduce number of hard disk write operations
45+ 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) {
46+ if (!stats_string.empty()) {
47+ std::vector<std::string> stats_vector;
48+ boost::split(stats_vector, stats_string, boost::is_any_of("|"));
49+ if (stats_vector.size() != nr_entries) {
50+ throw GameDataError("wrong number of %s statistics - expected %" PRIuS " but got %" PRIuS, description.c_str(), nr_entries, stats_vector.size());
51+ }
52+ for (size_t j = 0; j < nr_entries; ++j) {
53+ stats->at(ware_index)[j] = static_cast<unsigned int>(atoi(stats_vector.at(j).c_str()));
54+ }
55+ } else if (nr_entries > 0) {
56+ throw GameDataError("wrong number of %s statistics - expected %" PRIuS " but got 0", description.c_str(), nr_entries);
57+ }
58+ };
59
60 for (uint32_t i = 0; i < current_produced_statistics_.size(); ++i)
61 ware_productions_[i].resize(nr_entries);
62
63 for (uint16_t i = 0; i < nr_wares; ++i) {
64- std::string name = fr.c_string();
65- DescriptionIndex idx = egbase().tribes().ware_index(name);
66+ const std::string name = fr.c_string();
67+ const DescriptionIndex idx = egbase().tribes().ware_index(name);
68 if (!egbase().tribes().ware_exists(idx)) {
69 log("Player %u statistics: unknown ware name %s", player_number(), name.c_str());
70 continue;
71 }
72
73 current_produced_statistics_[idx] = fr.unsigned_32();
74-
75- for (uint32_t j = 0; j < nr_entries; ++j)
76- ware_productions_[idx][j] = fr.unsigned_32();
77+ if (packet_version < 22) {
78+ for (uint32_t j = 0; j < nr_entries; ++j) {
79+ ware_productions_[idx][j] = fr.unsigned_32();
80+ }
81+ } else {
82+ parse_stats(&ware_productions_, idx, fr.c_string(), "produced");
83+ }
84 }
85
86 // Read consumption statistics
87@@ -1386,8 +1407,8 @@
88 ware_consumptions_[i].resize(nr_entries);
89
90 for (uint16_t i = 0; i < nr_wares; ++i) {
91- std::string name = fr.c_string();
92- DescriptionIndex idx = egbase().tribes().ware_index(name);
93+ const std::string name = fr.c_string();
94+ const DescriptionIndex idx = egbase().tribes().ware_index(name);
95 if (!egbase().tribes().ware_exists(idx)) {
96 log("Player %u consumption statistics: unknown ware name %s", player_number(),
97 name.c_str());
98@@ -1395,9 +1416,14 @@
99 }
100
101 current_consumed_statistics_[idx] = fr.unsigned_32();
102-
103- for (uint32_t j = 0; j < nr_entries; ++j)
104- ware_consumptions_[idx][j] = fr.unsigned_32();
105+ // TODO(GunChleoc): Get rid of this savegame compatibility code after build 21
106+ if (packet_version < 22) {
107+ for (uint32_t j = 0; j < nr_entries; ++j) {
108+ ware_consumptions_[idx][j] = fr.unsigned_32();
109+ }
110+ } else {
111+ parse_stats(&ware_consumptions_, idx, fr.c_string(), "consumed");
112+ }
113 }
114
115 // Read stock statistics
116@@ -1408,15 +1434,20 @@
117 ware_stocks_[i].resize(nr_entries);
118
119 for (uint16_t i = 0; i < nr_wares; ++i) {
120- std::string name = fr.c_string();
121- DescriptionIndex idx = egbase().tribes().ware_index(name);
122+ const std::string name = fr.c_string();
123+ const DescriptionIndex idx = egbase().tribes().ware_index(name);
124 if (!egbase().tribes().ware_exists(idx)) {
125 log("Player %u stock statistics: unknown ware name %s", player_number(), name.c_str());
126 continue;
127 }
128
129- for (uint32_t j = 0; j < nr_entries; ++j)
130- ware_stocks_[idx][j] = fr.unsigned_32();
131+ if (packet_version < 22) {
132+ for (uint32_t j = 0; j < nr_entries; ++j) {
133+ ware_stocks_[idx][j] = fr.unsigned_32();
134+ }
135+ } else {
136+ parse_stats(&ware_stocks_, idx, fr.c_string(), "stock");
137+ }
138 }
139
140 // All statistics should have the same size
141@@ -1439,39 +1470,52 @@
142 }
143
144 /**
145- * Write statistics data to the give file
146+ * Write statistics data to the given file
147 */
148 void Player::write_statistics(FileWrite& fw) const {
149+ // Save stats as a single string to reduce number of hard disk write operations
150+ const auto write_stats = [&fw](const std::vector<std::vector<uint32_t>>& stats, const DescriptionIndex ware_index) {
151+ std::ostringstream oss("");
152+ if (!stats[ware_index].empty()) {
153+ for (uint32_t i = 0; i < stats[ware_index].size() - 1; ++i) {
154+ oss << stats[ware_index][i] << "|";
155+ }
156+ oss << stats[ware_index][stats[ware_index].size() - 1];
157+ }
158+ fw.c_string(oss.str());
159+ };
160+
161+ const Tribes& tribes = egbase().tribes();
162+ const std::set<DescriptionIndex>& tribe_wares = tribe().wares();
163+ const size_t nr_wares = tribe_wares.size();
164+
165 // Write produce statistics
166- fw.unsigned_16(current_produced_statistics_.size());
167+ fw.unsigned_16(nr_wares);
168 fw.unsigned_16(ware_productions_[0].size());
169
170- for (uint8_t i = 0; i < current_produced_statistics_.size(); ++i) {
171- fw.c_string(egbase().tribes().get_ware_descr(i)->name());
172- fw.unsigned_32(current_produced_statistics_[i]);
173- for (uint32_t j = 0; j < ware_productions_[i].size(); ++j)
174- fw.unsigned_32(ware_productions_[i][j]);
175+ for (const DescriptionIndex ware_index : tribe_wares) {
176+ fw.c_string(tribes.get_ware_descr(ware_index)->name());
177+ fw.unsigned_32(current_produced_statistics_[ware_index]);
178+ write_stats(ware_productions_, ware_index);
179 }
180
181 // Write consume statistics
182- fw.unsigned_16(current_consumed_statistics_.size());
183+ fw.unsigned_16(nr_wares);
184 fw.unsigned_16(ware_consumptions_[0].size());
185
186- for (uint8_t i = 0; i < current_consumed_statistics_.size(); ++i) {
187- fw.c_string(egbase().tribes().get_ware_descr(i)->name());
188- fw.unsigned_32(current_consumed_statistics_[i]);
189- for (uint32_t j = 0; j < ware_consumptions_[i].size(); ++j)
190- fw.unsigned_32(ware_consumptions_[i][j]);
191+ for (const DescriptionIndex ware_index : tribe_wares) {
192+ fw.c_string(tribes.get_ware_descr(ware_index)->name());
193+ fw.unsigned_32(current_consumed_statistics_[ware_index]);
194+ write_stats(ware_consumptions_, ware_index);
195 }
196
197 // Write stock statistics
198- fw.unsigned_16(ware_stocks_.size());
199+ fw.unsigned_16(nr_wares);
200 fw.unsigned_16(ware_stocks_[0].size());
201
202- for (uint8_t i = 0; i < ware_stocks_.size(); ++i) {
203- fw.c_string(egbase().tribes().get_ware_descr(i)->name());
204- for (uint32_t j = 0; j < ware_stocks_[i].size(); ++j)
205- fw.unsigned_32(ware_stocks_[i][j]);
206+ for (const DescriptionIndex ware_index : tribe_wares) {
207+ fw.c_string(tribes.get_ware_descr(ware_index)->name());
208+ write_stats(ware_stocks_, ware_index);
209 }
210 }
211 }
212
213=== modified file 'src/logic/player.h'
214--- src/logic/player.h 2018-07-12 04:41:20 +0000
215+++ src/logic/player.h 2018-07-13 13:41:35 +0000
216@@ -579,7 +579,7 @@
217
218 std::vector<uint32_t> const* get_ware_stock_statistics(DescriptionIndex const) const;
219
220- void read_statistics(FileRead&);
221+ void read_statistics(FileRead&, uint16_t packet_version);
222 void write_statistics(FileWrite&) const;
223 void read_remaining_shipnames(FileRead&, uint16_t packet_version);
224 void write_remaining_shipnames(FileWrite&) const;
225
226=== modified file 'src/logic/save_handler.cc'
227--- src/logic/save_handler.cc 2018-04-07 16:59:00 +0000
228+++ src/logic/save_handler.cc 2018-07-13 13:41:35 +0000
229@@ -83,14 +83,11 @@
230 * @return true if game should be saved ad next think().
231 */
232 bool SaveHandler::check_next_tick(Widelands::Game& game, uint32_t realtime) {
233-
234 // Perhaps save is due now?
235 if (autosave_interval_in_ms_ <= 0 || next_save_realtime_ > realtime) {
236 return false; // no autosave or not due, yet
237 }
238
239- next_save_realtime_ = realtime + autosave_interval_in_ms_;
240-
241 // check if game is paused (in any way)
242 if (game.game_controller()->is_paused_or_zero_speed()) {
243 return false;
244@@ -125,11 +122,16 @@
245 g_fs->fs_rename(backup_filename, complete_filename);
246 }
247 // Wait 30 seconds until next save try
248- next_save_realtime_ += 30000;
249+ next_save_realtime_ = SDL_GetTicks() + 30000;
250 } else {
251 // if backup file was created, time to remove it
252- if (backup_filename.length() > 0 && g_fs->file_exists(backup_filename))
253+ if (backup_filename.length() > 0 && g_fs->file_exists(backup_filename)) {
254 g_fs->fs_unlink(backup_filename);
255+ }
256+
257+ // Count save interval from end of save.
258+ // This prevents us from going into endless autosave cycles if the save should take longer than the autosave interval.
259+ next_save_realtime_ = SDL_GetTicks() + autosave_interval_in_ms_;
260 }
261 return result;
262 }
263@@ -138,12 +140,11 @@
264 * Check if autosave is needed and allowed or save was requested by user.
265 */
266 void SaveHandler::think(Widelands::Game& game) {
267-
268 if (!allow_saving_ || game.is_replay()) {
269 return;
270 }
271
272- uint32_t realtime = SDL_GetTicks();
273+ const uint32_t realtime = SDL_GetTicks();
274 initialize(realtime);
275
276 // Are we saving now?
277@@ -185,7 +186,6 @@
278 log("Autosave: save took %d ms\n", SDL_GetTicks() - realtime);
279 game.get_ibase()->log_message(_("Game saved"));
280 saving_next_tick_ = false;
281-
282 } else {
283 saving_next_tick_ = check_next_tick(game, realtime);
284 }