Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Production queue gets slower as the number of items increases #2188

Open
flaviojs opened this issue Jun 27, 2018 · 12 comments

Comments

Projects
None yet
5 participants
@flaviojs
Copy link
Contributor

commented Jun 27, 2018

Environment

  • FreeOrion Version: v0.4.8+ (master at ae39545)
  • Operating System: Linux Mint 18 Sarah
  • Graphic card used: Advanced Micro Devices, Inc. [AMD/ATI] RV710/M92 [Mobility Radeon HD 4530/4570/545v]
  • Fetched as
    • Compiled from source

Description

I already noticed everything getting slower as the turn numbers increased, but had no idea why.
By chance I discovered one cause for that. :)

I was in a game that had lots of entries in the production queue and every click/action on the queue was freezing the game for a few seconds.
I'm not sure how many items there were, but it displayed "Never" as the finish turn after a certain number (there must be a limit in the code).

I was almost at the end game and owned over half of the systems.
I decided to delete most shipyard upgrades from the production queue, and saw the game freeze time decreasing as I removed them.

This is a clear indication that the number of items in the production queue is a cause of the freezes.

Expected Result

No freeze time when I click on an item of a very big production queue.

Steps to reproduce

  • Add stuff to the production queue until you can see the game freeze for a bit when you click on a queue item.
  • Delete items from the queue and see the freeze time decrease.
@flaviojs

This comment has been minimized.

Copy link
Contributor Author

commented Jun 27, 2018

I looked at the source and the likely root cause is the use of std::distance, used here in a simple click:

m_build_designator_wnd->CenterOnBuild(std::distance(m_queue_wnd->GetQueueListBox()->begin(), it));

with iterators of std::list, declared here:
typedef std::list<std::shared_ptr<Row>>::iterator iterator;

Since std::list is a linked list and the most common case is interacting with the end of the queue (with what was just added), then std::distance will do a full list traversal most of the time: O(n)

A simplistic way to fix this would be to replace the std::list with std::vector, that way std::distance would be a simple arithmetic calculation: O(1)
(would need to handle invalidation of iterators)

A different way to fix this would be to add an index variable to the Row structure, updating it when the list is modified, and using it instead of std::distance.

@Vezzra

This comment has been minimized.

Copy link
Member

commented Jun 27, 2018

Hm, seems you've already some pretty concrete ideas how to improve the code section in question. Feel free (and encouraged!) to put up a PR implementing these improvements. 😃

@Dilvish-fo

This comment has been minimized.

Copy link
Member

commented Jun 28, 2018

I'd be interested in hearing your feedback after you try that adjustment. It would be very nice if something like that so simple (edited: I don't think that would be as simple a change as you think) could make a noticeable difference.

I suspect though that you are running into a price we pay for the Imperial Stockpile. Please see the discussion in #1606 regarding the 20-40-fold slowdown in the production queue completion time projections, to allow for the Imperial Stockpile mechanics. For typically large production queues this was still working out with an acceptable delay in my tests, but that was on a moderately powerful desktop machine, and you might be running a larger production queue than I tested as well.

One thing I had contemplated was making a dual-approach ProductionQueue implementation, so that if a ResourceGroup had no items in it which were enabled for the Imperial Stockpile, all production in that ResourceGroup could be handled with the tremendously faster dynamic-programming type projections. For that to really work well, we'd probably also need a way (UI checkbox, or possibly game rule, which could have benefits for AI processing time also) to control whether the new items placed on the queue are by default enabled for the Imperial Stockpile or not.

@flaviojs

This comment has been minimized.

Copy link
Contributor Author

commented Jun 28, 2018

  1. Using std::vector would be a guaranteed performance improvement, but the iterator invalidation must not be underestimated... the impact depends on your code practices.
    If you already assume iterators invalidate when the container is modified, then all will be fine.
    If not, then you will start getting unexpected and hard to debug problems (whole code would need a review).

  2. Adding an index variable to Row is a tradeoff: the game will use more memory, will be faster in operations that don't modify the ListBox, and will have an unknown speed change in operations that modify the ListBox contents.

So... right now the iterator remains valid when the ListBox changes. Is this intended?
If it is or if you want to play it safe, then option 2 is more appropriate, otherwise option 1 is the best choice.

An example to put things in perceptive:
You are moving an item in the ListBox.
A signal is sent with an iterator and has 2 listeners.
The first listener modifies the ListBox contents!!!
If the iterator remains valid, then the second listener will work as expected.
If the iterator is invalidated, then the second listener might get another row or access freed memory.
The same problems can apply to the code that triggers the signal.

@flaviojs

This comment has been minimized.

Copy link
Contributor Author

commented Jun 29, 2018

By using tail -f ~/.local/share/freeorion/freeorion.log, it appears that it's doing calculations during the freeze (this is mid game, I can already see the freeze clearly, unfreezes around the last message):

20:56:53.286647 [debug] client : Order.cpp:913 : ProductionQueueOrder place ProductionItem: BT_SHIP name: Advanced Troops x5id: 4939
20:56:53.287021 [debug] client : Empire.cpp:2169 : ========= Production Update for empire: 1 ========
20:56:53.331537 [debug] client : ProductionQueue.cpp:794 : ProductionQueue::Update: Simulating future turns of production queue
20:56:53.601024 [debug] client : ProductionQueue.cpp:878 : ProductionQueue::Update: Projections took 269313 microseconds with 909.773 total Production Points
20:56:53.622811 [debug] client : MapWnd.cpp:3895 : MapWnd::InitStarlaneRenderingBuffers
20:56:53.649512 [debug] timer : ScopedTimer.cpp:34 : MapWnd::InitStarlaneRenderingBuffers time:       26 ms
20:56:54.593997 [debug] client : EncyclopediaDetailPanel.cpp:2237 : default enemy stats:: tech_level: 0.4375   DR: 8.75   attack: 14.8125
20:56:54.928381 [debug] client : Universe.cpp:1478 : Issue times: planet species: 0.578 ship species: 1.519 specials: 52.329 techs: 46.754 buildings: 11.304 hulls/parts: 55.168 fields: 13.817
20:56:54.928530 [debug] client : Universe.cpp:1485 : Evaluation time: 505.965 reorder time: 0.243
20:56:54.932291 [debug] timer : ScopedTimer.cpp:34 : Universe::UpdateMeterEstimatesImpl on 1 objects time:      337 ms
20:56:55.248058 [debug] client : Universe.cpp:1478 : Issue times: planet species: 0.568 ship species: 1.507 specials: 57.046 techs: 44.277 buildings: 5.832 hulls/parts: 38.962 fields: 2.498
20:56:55.248208 [debug] client : Universe.cpp:1485 : Evaluation time: 508.129 reorder time: 0.243
20:56:55.252181 [debug] timer : ScopedTimer.cpp:34 : Universe::UpdateMeterEstimatesImpl on 1 objects time:      319 ms
20:56:55.253059 [debug] client : Universe.cpp:2822 : Universe::Delete with ID: -2
20:56:55.873938 [debug] timer : ScopedTimer.cpp:189 : EncyclopediaDetailPanel::DoLayout                         time:     2016 µs

The std::list problem is peanuts compared to doing calculations in the GUI thread.
If you move calculations to a separate thread it will definitely avoid freezing.
Basically, change synchronous updates to asynchronous ones.

@Vezzra

This comment has been minimized.

Copy link
Member

commented Jul 1, 2018

Hm, these calculations are necessary to display correct info on the production queue items... so moving them into a separate thread might help with UI freezing, but won't that mean that the updated information gets displayed with a noticeable, or even problematic delay?

When you manipulate the queue, and the numbers don't update, but the UI responds smoothly, things might get confusing for the player, wouldn't it?

I'm wondering if that would really be an improvement...

@geoffthemedio

This comment has been minimized.

Copy link
Member

commented Jul 1, 2018

Could add a "processing / updating" overlay while it's thinking about it.

@Vezzra

This comment has been minimized.

Copy link
Member

commented Jul 1, 2018

Yep, that could work.

@flaviojs

This comment has been minimized.

Copy link
Contributor Author

commented Jul 1, 2018

After adding some debug stuff to the source, EncyclopediaDetailPanel appears to be the main contributor to the freeze times.

In both examples the game unfreezes at the end.
I used something similar to ScopedTimer to log >=100ms function times to the console (>=500ms for GG::GUI).
Format: [log time] [thread] pretty function [extra info] function time

Example 1 - Clicking on a ship in the production queue:

[18:59:29.565624] [7f6ac7ffe700] void {anonymous}::StoreTargetsAndCausesOfEffectsGroupsWorkItem::operator()() time:      155 ms
[18:59:29.719816] [7f6ac6614700] void {anonymous}::StoreTargetsAndCausesOfEffectsGroupsWorkItem::operator()() time:      295 ms
[18:59:29.726142] [7f6ac6e15700] void {anonymous}::StoreTargetsAndCausesOfEffectsGroupsWorkItem::operator()() time:      270 ms
[18:59:29.743501] [7f6aed3f38c0] void Universe::GetEffectsAndTargets(Effect::TargetsCauses&, const std::vector<int>&) time:      551 ms
[18:59:29.748047] [7f6aed3f38c0] void Universe::UpdateMeterEstimatesImpl(const std::vector<int>&, bool) time:      556 ms
[18:59:29.748132] [7f6aed3f38c0] void Universe::UpdateMeterEstimates(int, bool) time:      556 ms
[18:59:30.099567] [7f6ac4e11700] void {anonymous}::StoreTargetsAndCausesOfEffectsGroupsWorkItem::operator()() time:      131 ms
[18:59:30.203483] [7f6ac6ffc700] void {anonymous}::StoreTargetsAndCausesOfEffectsGroupsWorkItem::operator()() time:      226 ms
[18:59:30.306284] [7f6aed3f38c0] void Universe::GetEffectsAndTargets(Effect::TargetsCauses&, const std::vector<int>&) time:      557 ms
[18:59:30.307634] [7f6aed3f38c0] void Universe::UpdateMeterEstimatesImpl(const std::vector<int>&, bool) time:      558 ms
[18:59:30.307774] [7f6aed3f38c0] void Universe::UpdateMeterEstimates(int, bool) time:      559 ms
[18:59:30.308871] [7f6aed3f38c0] void {anonymous}::RefreshDetailPanelShipDesignTag(const string&, const string&, std::__cxx11::string&, std::shared_ptr<GG::Texture>&, std::shared_ptr<GG::Texture>&, int&, float&, std::__cxx11::string&, std::__cxx11::string&, std::__cxx11::string&, std::__cxx11::string&, GG::Clr&) time:     1119 ms
[18:59:30.308911] [7f6aed3f38c0] void {anonymous}::GetRefreshDetailPanelInfo(const string&, const string&, std::__cxx11::string&, std::shared_ptr<GG::Texture>&, std::shared_ptr<GG::Texture>&, int&, float&, std::__cxx11::string&, std::__cxx11::string&, std::__cxx11::string&, std::__cxx11::string&, GG::Clr&, std::weak_ptr<const ShipDesign>&, GG::X) time:     1119 ms
[18:59:30.948794] [7f6aed3f38c0] void EncyclopediaDetailPanel::RefreshImpl() time:     1759 ms
[18:59:30.951557] [7f6aed3f38c0] virtual void EncyclopediaDetailPanel::PreRender() time:     1762 ms
[18:59:30.951601] [7f6aed3f38c0] static void GG::GUI::PreRenderWindow(GG::Wnd*) [EncyclopediaDetailPanel] time:     1762 ms
[18:59:30.952226] [7f6aed3f38c0] static void GG::GUI::PreRenderWindow(GG::Wnd*) [BuildDesignatorWnd] time:     1763 ms
[18:59:30.952259] [7f6aed3f38c0] static void GG::GUI::PreRenderWindow(GG::Wnd*) [ProductionWnd] time:     1764 ms
[18:59:30.952303] [7f6aed3f38c0] virtual void GG::GUI::PreRender() time:     1767 ms

Example 2 - Moving the ship in the production queue:

[19:00:01.200551] [7f6aed3f38c0] void BuildDesignatorWnd::BuildSelector::Refresh() time:      132 ms
[19:00:01.200590] [7f6aed3f38c0] void BuildDesignatorWnd::Update() time:      132 ms
// TODO find missing time
[19:00:01.221757] [7f6aed3f38c0] void GG::Wnd::HandleEvent(const GG::WndEvent&) [{ProductionWnd.cpp}::ProdQueueListBox] time:     1011 ms
[19:00:01.221843] [7f6aed3f38c0] void GG::Wnd::HandleEvent(const GG::WndEvent&) [{ProductionWnd.cpp}::QueueRow] time:     1011 ms
[19:00:01.223984] [7f6aed3f38c0] void GG::GUIImpl::HandleMouseButtonRelease(unsigned int, const GG::Pt&, int) time:     1014 ms
[19:00:01.224039] [7f6aed3f38c0] void GG::GUI::HandleGGEvent(GG::GUI::EventType, GG::Key, uint32_t, GG::Flags<GG::ModKey>, const GG::Pt&, const GG::Pt&, const string*) time:     1014 ms
[19:00:01.224360] [7f6aed3f38c0] virtual void GG::SDLGUI::HandleSystemEvents() time:     1015 ms
[19:00:01.687858] [7f6ac77fd700] void {anonymous}::StoreTargetsAndCausesOfEffectsGroupsWorkItem::operator()() time:      111 ms
[19:00:01.745085] [7f6ac7ffe700] void {anonymous}::StoreTargetsAndCausesOfEffectsGroupsWorkItem::operator()() time:      233 ms
[19:00:01.764791] [7f6aed3f38c0] void Universe::GetEffectsAndTargets(Effect::TargetsCauses&, const std::vector<int>&) time:      473 ms
[19:00:01.766114] [7f6aed3f38c0] void Universe::UpdateMeterEstimatesImpl(const std::vector<int>&, bool) time:      475 ms
[19:00:01.766205] [7f6aed3f38c0] void Universe::UpdateMeterEstimates(int, bool) time:      475 ms
[19:00:02.190712] [7f6ac77fd700] void {anonymous}::StoreTargetsAndCausesOfEffectsGroupsWorkItem::operator()() time:      152 ms
[19:00:02.223245] [7f6ac7ffe700] void {anonymous}::StoreTargetsAndCausesOfEffectsGroupsWorkItem::operator()() time:      238 ms
[19:00:02.243439] [7f6aed3f38c0] void Universe::GetEffectsAndTargets(Effect::TargetsCauses&, const std::vector<int>&) time:      476 ms
[19:00:02.244707] [7f6aed3f38c0] void Universe::UpdateMeterEstimatesImpl(const std::vector<int>&, bool) time:      477 ms
[19:00:02.244758] [7f6aed3f38c0] void Universe::UpdateMeterEstimates(int, bool) time:      477 ms
[19:00:02.246120] [7f6aed3f38c0] void {anonymous}::RefreshDetailPanelShipDesignTag(const string&, const string&, std::__cxx11::string&, std::shared_ptr<GG::Texture>&, std::shared_ptr<GG::Texture>&, int&, float&, std::__cxx11::string&, std::__cxx11::string&, std::__cxx11::string&, std::__cxx11::string&, GG::Clr&) time:      956 ms
[19:00:02.246206] [7f6aed3f38c0] void {anonymous}::GetRefreshDetailPanelInfo(const string&, const string&, std::__cxx11::string&, std::shared_ptr<GG::Texture>&, std::shared_ptr<GG::Texture>&, int&, float&, std::__cxx11::string&, std::__cxx11::string&, std::__cxx11::string&, std::__cxx11::string&, GG::Clr&, std::weak_ptr<const ShipDesign>&, GG::X) time:      956 ms
[19:00:02.885659] [7f6aed3f38c0] void EncyclopediaDetailPanel::RefreshImpl() time:     1597 ms
[19:00:02.888408] [7f6aed3f38c0] virtual void EncyclopediaDetailPanel::PreRender() time:     1600 ms
[19:00:02.888451] [7f6aed3f38c0] static void GG::GUI::PreRenderWindow(GG::Wnd*) [EncyclopediaDetailPanel] time:     1600 ms
[19:00:02.892270] [7f6aed3f38c0] static void GG::GUI::PreRenderWindow(GG::Wnd*) [BuildDesignatorWnd] time:     1632 ms
[19:00:02.892309] [7f6aed3f38c0] static void GG::GUI::PreRenderWindow(GG::Wnd*) [ProductionWnd] time:     1663 ms
[19:00:02.892353] [7f6aed3f38c0] virtual void GG::GUI::PreRender() time:     1667 ms

EncyclopediaDetailPanel is waiting synchronously on Universe estimates!!
I guess it should show "loading..." and build the contents in a different thread?

@Dilvish-fo

This comment has been minimized.

Copy link
Member

commented Jul 1, 2018

EncyclopediaDetailPanel is waiting synchronously on Universe estimates!!

There is only one aspect of the client that currently can be multithreaded (processing of effects, if you have the option set for that to be multithreaded), but even that is essentially just a temporary ballooning of threads in what in all other respects is a single-threaded synchronous process. Reorganizing the client to be fully multithreaded has been noted as a would-be-nice development task for some time now, but hasn't really been a high enough priority for anyone to get around to acting on it If you'd like to tackle that, it would be welcome. Though I'd probably recommend you start with some smaller tasks first to get more familiar with the code base.

@flaviojs

This comment has been minimized.

Copy link
Contributor Author

commented Jul 3, 2018

Universe stuff doesn't seem to be multithread-friendly at the moment...

Maybe an invalidating mechanism like the one used to prerender in the gui?
That should speed things up, possibly removing the need for threads.

(edit) Hmm, this is going off topic so I'll stop here. If I decide to go on, I'll create a thread in the forum.

@Morlic-fo

This comment has been minimized.

Copy link
Contributor

commented Sep 17, 2018

Try adding production queue entries in a new game - 10 systems, no AI. Effect execution and production simulation is then trivial. Production queue lag is still very noticeable for me.

Profiling indicates (at least part of) the underlying issue is that ProductionWnd::UpdateQueue() and ResearchWnd::UpdateQueue() rebuild the entire ProductionQueueWnd/ResearchQueueWnd content from scratch. This includes repopulating the dropdowns, creating the icons, recreating turn progress bar...
https://github.com/freeorion/freeorion/blob/master/UI/ResearchWnd.cpp#L581
https://github.com/freeorion/freeorion/blob/master/UI/ProductionWnd.cpp#L1069

I expect that updating the existing UI elements with the changes instead of rebuilding everything from scratch would provide a huge speedup. While progressbar and texts must still be updated for all/most items (Updating some attributes should be faster than rebuilding and rearranging those elements though), there is no need to recreate the icons, the QuantitySelectors, the overall queue layout...

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.