Console slowness then crash

Heya,

I've just started using the console in 0.9.7, and am having a couple problems:

Firstly, it's incredibly slow. Watch these two movies to see:
http://chunkyks.com/videos/slowloop.mov
http://chunkyks.com/videos/fasterloop.mov

The only difference between these two is a call to mConsole->addText(line);

Further experimentation shows that this problem only occurs when the console has to alter the scrollbar [ie, create one, or modify an already-existing one]. Until then, it runs fine. For example, if I make my console take up the entire screen, then it works fine for the command I typed plus entries 1..29.


Secondly, I get a weird issue where quickgui's console doesn't take the last few things I do there [if you look at slowloop.mov again, you'll see that the end of the console only goes up to 29 when it should have gone to 100 - the first line is the line I typed, and it holds thirty lines in total].

The next time I try to type something in, I get a crash. The last bit of the backtrace is this:
#0 0x00000000 in ?? ()
#1 0x00189bfc in QuickGUI::List::removeItem (this=0x2081e00, index=0) at /Users/chunky/src/tuxwars3/src/libs/QuickGUI/src/QuickGUIList.cpp:232
#2 0x0017ccb2 in QuickGUI::Console::addText (this=0x2081a00, text=@0xbfffed40) at /Users/chunky/src/tuxwars3/src/libs/QuickGUI/src/QuickGUIConsole.cpp:60
#3 0x001434af in TWGUI::addConsoleLine (line=0x1bb6bb1c "30", alsoprint=true) at /Users/chunky/src/tuxwars3/src/gui/maingui.cpp:109
#4 0x0016e1fe in TWluaB_print (L=0x1f0c150) at /Users/chunky/src/tuxwars3/src/scripting/scripthost.cpp:307
#5 0x00153ee3 in luaD_precall (L=0x1f0c150, func=0x200c8a8, nresults=0) at /Users/chunky/src/tuxwars3/src/libs/lua/ldo.c:319

The specific line it crashes at is:
(*it).second->setYPosition(counter * mItemHeight);
At the crash, counter is 1 and mItemHeight is 16.7999992

I'm not familiar enough with QuickGUI to even hazard a guess at what's happening. It *seems* like what's happening is lines added to the console via the addLine method are missing something being changed in the console object, and then later when trying to remove the first item, something is unaccounted for. But that's a wild guess off the top of my head

Thank-you very much,
Gary (-;

More information: Adding mConsole->setMaxLines(5000); gives me a much larger dataset to work with.
Apologies for this movie being a lot larger, I think it makes stuff a lot clearer though: http://chunkyks.com/videos/slowsdownloop.mov

If you watch it through, you'll see that each time something is added to the console, the loop goes a little slower. At the start it's too-fast-to-see, but by the time I get down above 150 or so, it runs slower and slower. As I type this we're at about 350, and there's about four seconds of computation for every entry.

I have a hunch that this is a "Shlemiel the painter" moment. Again, not quite sure where to look though

Gary (-;

And having just spent most of today trying to make shark do something useful:

http://chunkyks.com/quickguiconsoleprofile.png

Gary (-;

Thanks for the input! It definately looks like there needs to be some optimization here.

Each character printed to the screen is a quad. Even whitespace are quads. (for highlighting purposes) When you add items to the console such that it takes up more screen space alloted for the text, the scroll bars become visible. Every time you add a line, all previous lines have to be shifted up. I'm not exactly sure where the slowdown occurs, we'll need to profile it (can be as simple as time stamps to the ogre.log file) to see what operations take up the most time.

These days, any time I get I put into the SkinSet Editor I want to make, I want to update how SkinSets work. Fill out the features and then optimize later on, right?

[edit]
What IDE are you using? Is it possible to step in and see why you get a crash when pressing Enter with a full console? You should have seen the last 30 lines of text, and not the first 30.
[/edit]

Thanks for the input! It definately looks like there needs to be some optimization here.

Each character printed to the screen is a quad. Even whitespace are quads. (for highlighting purposes) When you add items to the console such that it takes up more screen space alloted for the text, the scroll bars become visible. Every time you add a line, all previous lines have to be shifted up. I'm not exactly sure where the slowdown occurs, we'll need to profile it (can be as simple as time stamps to the ogre.log file) to see what operations take up the most time.

That's what the big image is - it's the OSX profiler, called Shark. What you're seeing there is a whole lot of time being spent molesting stuff in std::string, and then 8% of the time in QuickGUI::QuadContainer::addChildRenderable. [at least, that's what I *think* I'm looking at]

These days, any time I get I put into the SkinSet Editor I want to make, I want to update how SkinSets work. Fill out the features and then optimize later on, right?

Ha. Might be a good time to figure out how to optimise a little, I think . I honestly just don't have much of a concept of how QuickGUI works, sadly.

Regarding QuickGUI specifically, perhaps from my understanding of your description, then there's no need to build quads like that? Once you've built each one for each character, can it be cached and never re-created?

What IDE are you using? Is it possible to step in and see why you get a crash when pressing Enter with a full console? You should have seen the last 30 lines of text, and not the first 30.

Mh. I'm using XCode [which uses GDB as its debugger]. Experimentally, I set the max number of console lines to three, then just typed in four lines. Deliberately, none of those use my manual addLine function, they're just what happens when you type stuff into the console in quickgui and get automatically added. [If you don't prefix / on anything typed into the console, then my software currently just ignores it].

Oooo, re-reading what you said, what you're seeing *is* the crash lines. The crash is occurring when QuickGUI attempts to remove the top item from the console window [the oldest entry]

The crash is at the top, and the callstack goes down. But anyways, here's a complete one, skipping out my lua stuff in the middle as described in the paragraph above this one:

(gdb) bt
#0 0x00000008 in ?? ()
#1 0x00189bf4 in QuickGUI::List::removeItem (this=0x2081e00, index=0) at /Users/chunky/src/tuxwars3/src/libs/QuickGUI/src/QuickGUIList.cpp:232
#2 0x0017ccaa in QuickGUI::Console::addText (this=0x2081a00, text=@0xbffff310) at /Users/chunky/src/tuxwars3/src/libs/QuickGUI/src/QuickGUIConsole.cpp:60
#3 0x0017cd77 in QuickGUI::Console::onEnterPressed (this=0x2081a00, args=@0xbffff3b0) at /Users/chunky/src/tuxwars3/src/libs/QuickGUI/src/QuickGUIConsole.cpp:106
#4 0x0017f6e5 in QuickGUI::MemberFunctionPointer<QuickGUI::Console>::execute (this=0x1fe25a0, args=@0xbffff3b0) at QuickGUIMemberFunctionPointer.h:47
#5 0x001be2e4 in QuickGUI::TextBox::onEnterPressed (this=0x2085600, args=@0xbffff3b0) at /Users/chunky/src/tuxwars3/src/libs/QuickGUI/src/QuickGUITextBox.cpp:531
#6 0x001be4d2 in QuickGUI::TextBox::onKeyUp (this=0x2085600, args=@0xbffff470) at /Users/chunky/src/tuxwars3/src/libs/QuickGUI/src/QuickGUITextBox.cpp:636
#7 0x001c1719 in QuickGUI::MemberFunctionPointer<QuickGUI::TextBox>::execute (this=0x1fe2420, args=@0xbffff470) at QuickGUIMemberFunctionPointer.h:47
#8 0x001d141a in QuickGUI::Widget::fireEvent (this=0x2085600, e=QuickGUI::Widget::EVENT_KEY_UP, args=@0xbffff470) at /Users/chunky/src/tuxwars3/src/libs/QuickGUI/src/QuickGUIWidget.cpp:1167
#9 0x0018c076 in QuickGUI::GUIManager::injectKeyUp (this=0x1fd6c00, kc=@0xbffff4c8) at /Users/chunky/src/tuxwars3/src/libs/QuickGUI/src/QuickGUIManager.cpp:371
#10 0x0000320e in TWInput::keyReleased (this=0x1fe8ae0, e=@0x1bb65cec) at /Users/chunky/src/tuxwars3/src/game/input.cpp:195
#11 0x001e232e in OIS::MacKeyboard::capture (this=0x1fe8c40) at /Users/chunky/src/ogre/ois/Mac/XCode-2.2/../../src/mac/MacKeyboard.cpp:154
#12 0x0000337e in TWInput::captureEvents (this=0x1fe8ae0, mouse=true, keyboard=true, joystick=true) at /Users/chunky/src/tuxwars3/src/game/input.cpp:114
#13 0x00141a83 in TWMain::main_loop (this=0x1f0c0f0) at /Users/chunky/src/tuxwars3/src/game/maingame.cpp:233
#14 0x00002941 in main (argc=1, argv=0xbffff6f4) at /Users/chunky/src/tuxwars3/src/game/main.cpp:28
(gdb)

Thank-you very much,
Gary (-;

I think scrolling in general could use some optimizations, because oftentimes, a lot of the original quad remains the same and would not have to be rendered again... however, it would make things a little bit more complicated.

I'll try to look into this when I get some more time.

Quad Containers organize quads, and are used to update the vertex buffer, which performs the actual rendering. Quads are grouped by offset, and then grouped by material within that group, to minimize batching.

Probably the best route to optimize would be texture caching, like you suggest. I like the way RBGUI does its rendering, its a good reference. Instead of each window being a texture, I would probably make each QuadContainer be a texture. It would take some thought to implement this in a good way. (Using the RenderSystem::scissorTest function would make things a lot easier)

I still don't really understand from a super-high-level perspective ... What is it that's causing it to take longer and longer for each line added?

All other optimisations aside, it seems like adding a line to a textbox should be constant, and the fact that it's not implies that unneccessary functions are being called a lot?

For example, I don't know if this is how it's implemented, but if QuickGUI is recreating the entire textbox as a single quad every time a line is added from all of the characters in it, that would explain what I'm seeing. Wheras it would be much faster to create each line as its own quad as they get added, and then have ogre handle rendering multiple quads?

Once it's in-place and full, scrolling the console is immediate.

I tried the same thing but with a longer string:
http://chunkyks.com/videos/slowhellocookie.mov

What still seems really odd to me is that it's always brutally fast right up to the moment where the scrollbar is added, then every line added after that is superslow. With a shorter console:
http://chunkyks.com/videos/slowsmallconsole.mov

I simply have no idea what's going on and I'm getting semi-frustrated. Sorry if this post came out all grumpy-like, I'm mainly trying to help

Thank-you very much,
Gary (-;

Hey, you're posts are actually friendly in comparison to some I've seen in the past.

When the scroll bars appear, that means widgets are taking up more space than is given. (screen space is X by Y dimensions, but you are using X by Y+Z dimensions, for example)

The ScrollPane widget is the actual size that is taken up by all the widgets. The List represents the screen space allotted. Whenever you add an item to the List, the ScrollPane is notified, and grows/shrinks to fit all the widgets. The ratio between ScrollPane size and List size represent the width or height of the scroll bar sliders. Whenever you scroll the list, every widget in the list is offset, which means all the quads are offset. Each quad needs to check if clipping needs to occur.

I'm still not sure why the slowdown occurs, it sounds like I would have to investigate on my own.

Any ideas or suggestions about this? It's been really frustrating me the last couple days :-/

Thanks,
Gary (-;

Sorry for the late response. The company I work for has a product coming out soon, so I haven't had a lot of time outside of work to do anything QuickGUI related. Is lots of console text a major element of your game? The optimization I want to do to rendering is not very trivial, it would take a large amount of time to implement.

It's not an element of the game, but I do want to be able to put useful information in there.

And it's all good, I have lots of patience and other stuff to work on, I just... this is hanging in the back of my mind, periodically annoying me

Gary (-;

So, apart from the performance issues, is anyone able to reproduce the crash?

On OSX, it's still crashing where it was before. On my windows box here, when I fill up the console with maxLines of text, the first line disappears but the lines currently in the box do not change, and subsequent lines don't appear to be added.

Can anyone else try creating a console and filling it, something like:

char line[50];
int i;
for(i = 0; i < 1000; i++) {
snprintf(line, sizeof(line), "This is line %i", i);
mConsole->addLine(line);
}


FWIW my entire QuickGUI constructor right now is:
TWGUI::TWGUI(Ogre::SceneManager *scnmgr, Ogre::Viewport *vp) {
mScnMgr = scnmgr;
mViewport = vp;

new QuickGUI::Root();

QuickGUI::SkinSetManager::getSingleton().loadSkin("qgui",QuickGUI::SkinSet::IMAGE_TYPE_PNG);
mGUIManager = QuickGUI::Root::getSingleton().createGUIManager(mViewport,"qgui");

mGUIManager->setSceneManager(mScnMgr);
mGUIManager->_notifyViewportDimensionsChanged();

mSheet = mGUIManager->getDefaultSheet();
mSheet->setFont("TuxWarsText");

mConsole = mSheet->createConsole();
mConsole->setDimensions(QuickGUI::Rect(8,400,350,300));
mConsole->addOnEnterPressedEventHandler(&TWGUI::onChatTBEnter, this);
mConsole->setMaxLines(15);
}


Thank-you very much,
Gary (-;

I've got this slowdown + crash too, at the same line with maxItems = 30.

Something with mTextList->removeItem seems to be wrong.

On windows and linux, the console just appears to simply stop working once it hits the limit. It's only on OSX that I see this crash.

The slowdown happens on all platforms and my game has reached the point where this is a prohibitive issue

Thanks,
Gary (-;

The slowdown happens on all platforms and my game has reached the point where this is a prohibitive issue

I'll work on this for the next release in hopes of resolving this problem. First I have to redo text rendering.

First I have to redo text rendering

My understanding is that that'll actually fix the bulk of the performance issues, right?

What's bugging me more right now is that it's still crashing and I can't figure out why

Thanks!
Gary (-;

My understanding is that that'll actually fix the bulk of the performance issues, right?

It should. The rendering system is totally changed from before, and clipping is handled by Ogre. Everything is texture cached, so performance costs will be from creating the textures. I can't imagine it being worse than the current method.

Yay! Now just the crash

Thank-you very much for all the good work,
Gary (-;

I too have just come across the crash when calling List::removeItem()

I think the crash is due to mItems.erase(iterator); changing the map that the iterator points to, if you then try to access the iterator without renewing it, you get an error.

I've tried changing the affending code that moves all the items that were below the one deleted up to fill it's vacated space but I've hit another problem.

Is it worth me spending more time trying to fix it or have you already fixed it or changed the code completely in future versions of QuickGUI?

Is it worth me spending more time trying to fix it or have you already fixed it or changed the code completely in future versions of QuickGUI?

I haven't yet re-created the Console widget, but I will. I wouldn't spend time looking for the problem, the underlying mechanics will be very different in the next version.

Ok, I'll ignore the problem for now, thanks for replying.