239 replies to this topic

[Ykkrosh]

Day 6 plus a half

(This was Thursday, but I got a bit distracted and failed to post here earlier.)

Did some more work on the profiler, primarily fixing some bugs and cleaning up code enough to commit it (here/here/here).

If anyone wants to test it, you should recompile the game then launch it and press F11 to enable the new profiler's HTTP output (it's disabled by default for performance and security), then open the file source/tools/profiler2/profiler2.html in a web browser. (I've only tested Firefox 7; browser compatibility isn't a priority). Then it should work, with luck.

One extra feature is that the code can add text annotations to each profile region, which are displayed as tooltips:



Holding the mouse over the "convert texture [...]" region pops up the box saying which texture it's converting. The "compress" in this image is happening in a secondary thread, so it overlaps many frames. (In practice the compression is done before running the game and cached, so this isn't normally a real slowdown). I think this makes it particularly useful for improving the game's startup/load performance, since we can see what files are taking a long time when they're first loaded.

Day not-counted

I subsequently played around with a few more things (not committed yet), mostly for fun rather than to be useful for the game, so they don't count as proper work. In particular, the profiler can display the GPU like a separate thread (using the GL_ARB_timer_query extension, supported on most NVIDIA and ATI/AMD cards with the proprietary drivers):



Here the CPU is the top group of coloured boxes, the GPU is the bottom group. This gives a nice view of the fancy things that graphics drivers do. At the start of the timeline (on the left), the CPU is rendering frame 4824 while the GPU is rendering frame 4822. That means the CPU is submitting a load of rendering commands, which get queued up for 10-20msec before the GPU (which is busy rendering an earlier frame) gets around to processing those commands and doing the actual rendering. On frame 4827 I did something to delay the CPU a bit. The GPU carried on rendering the queued frames, but then had to pause until frame 4827 was ready to render. After that, the CPU and GPU times wobble around a bit (but the GPU maintains a fairly smooth framerate) until the GPU has synchronised back to 2 frames behind the CPU.

One annoyance is that Intel drivers don't support GL_ARB_timer_query, and Intel GPUs are where optimisation matters most (since they're so slow). It turns out that the most recent ones have an extension called GL_INTEL_performance_queries, which sounded interesting, but there's no specification and it seems nobody has ever written anything about it. So I fiddled with it a bit and wrote some documentation of the extension. Not sure it's hugely useful, but at least it can give a reasonable indication of the time the GPU spends on each part of the rendering. (It only gives relative times, not absolute, so unfortunately it messes up the timeline view a bit, but it's better than nothing.)

[fabio]

Ykkrosh, on 05 November 2011 - 06:53 PM, said:

I subsequently played around with a few more things (not committed yet), mostly for fun rather than to be useful for the game, so they don't count as proper work. In particular, the profiler can display the GPU like a separate thread (using the GL_ARB_timer_query extension, supported on most NVIDIA and ATI/AMD cards with the proprietary drivers):



Here the CPU is the top group of coloured boxes, the GPU is the bottom group. This gives a nice view of the fancy things that graphics drivers do. At the start of the timeline (on the left), the CPU is rendering frame 4824 while the GPU is rendering frame 4822. That means the CPU is submitting a load of rendering commands, which get queued up for 10-20msec before the GPU (which is busy rendering an earlier frame) gets around to processing those commands and doing the actual rendering. On frame 4827 I did something to delay the CPU a bit. The GPU carried on rendering the queued frames, but then had to pause until frame 4827 was ready to render. After that, the CPU and GPU times wobble around a bit (but the GPU maintains a fairly smooth framerate) until the GPU has synchronised back to 2 frames behind the CPU.

One annoyance is that Intel drivers don't support GL_ARB_timer_query, and Intel GPUs are where optimisation matters most (since they're so slow). It turns out that the most recent ones have an extension called GL_INTEL_performance_queries, which sounded interesting, but there's no specification and it seems nobody has ever written anything about it. So I fiddled with it a bit and wrote some documentation of the extension. Not sure it's hugely useful, but at least it can give a reasonable indication of the time the GPU spends on each part of the rendering. (It only gives relative times, not absolute, so unfortunately it messes up the timeline view a bit, but it's better than nothing.)

Awesome work

Did you try it on Windows? On mesa drivers (intel included) there is some support for timer_query (EXT variant):
http://cgit.freedesk...p&q=timer_query
http://cgit.freedesk...ee/docs/GL3.txt

[Ykkrosh]

Sylvain Gadrat, on 03 November 2011 - 06:19 PM, said:

Just as a reminder, please keep the "EngineProfiling" wiki page up to date when integrated. It is an awsome wikipage

Okay, I'll try to update that within the next few days (when the profiler design is a bit more stable) - please remind me if I forget then

Quote

While talking about optimization, on the first post you talk about optimizing the pathfinder. Do you think your changes will impact the long pathfinder ? I am still musing about implementing hpa* whereas I terribly lack time. Note that it is just a question, not a request, your work is awsome and I lack time

Currently I'm only thinking of the short pathfinder, so it shouldn't affect that.

fabio, on 05 November 2011 - 08:52 PM, said:

Did you try it on Windows? On mesa drivers (intel included) there is some support for timer_query (EXT variant)

Yeah, I'm currently using Windows. I started with the ARB_timer_query because it's more powerful than EXT_timer_query - the EXT one can only measure relative times, not absolute times, so it can say how long each part of the rendering takes but can't say how far it's delayed behind the CPU, so you can't line the CPU and GPU up properly. But INTEL_performance_query has the same problem with only providing relative times, so I need to deal with that anyway, so I suppose I might as well add EXT_timer_query too. (Currently my GPU-timing code is hideous so I need to rewrite it all anyway )

[fabio]

OK, I tested it and it works as expected.

Just a couple of questions:
1) the profiler server starts when pressing F11 but can no longer be stopped?
2) the test fails with:

Running 255 tests....................................................................................................................................................................................................................................................Profiler2.cpp(187): Assertion failed: "m_Initialised"
Assertion failed: "m_Initialised"
Location: Profiler2.cpp:187 (RegisterCurrentThread)

Call stack:

(0x84a2f60) ./test() [0x84a2f60]
(0x8449fb4) ./test() [0x8449fb4]
(0x844a247) ./test() [0x844a247]
(0x844b184) ./test() [0x844b184]
(0x8286b0c) ./test() [0x8286b0c]
(0x834fc50) ./test() [0x834fc50]
(0xb6ec2e99) /lib/i386-linux-gnu/libpthread.so.0(+0x5e99) [0xb6ec2e99]
(0xb6e2c73e) /lib/i386-linux-gnu/libc.so.6(clone+0x5e) [0xb6e2c73e]

errno = 0 (No error reported here)
OS error = ?



In TestTextureConverter::test_convert_quality:
../../../source/graphics/tests/../../../source/graphics/tests/test_TextureConverter.h:78: Error: Expected ((m_VFS->LoadFile(dest, file, fileSize)) == INFO::OK), found ({ EB 51 FE FF FF FF FF FF  } != { 00 00 00 00 00 00 00 00  })
tex_codec.cpp(83): Function call failed: return value was -120101 (Unknown error (-120101, 0xFFFFFFFFFFFE2ADB))
Function call failed: return value was -120101 (Unknown error (-120101, 0xFFFFFFFFFFFE2ADB))
Location: tex_codec.cpp:83 (tex_codec_for_header)

Call stack:

(0x84a2f60) ./test() [0x84a2f60]
(0x8449fb4) ./test() [0x8449fb4]
(0x844a247) ./test() [0x844a247]
(0x844ae10) ./test() [0x844ae10]
(0x849632c) ./test() [0x849632c]
(0x8499b52) ./test() [0x8499b52]
(0x807166f) ./test() [0x807166f]
(0x805b4a5) ./test() [0x805b4a5]
(0x8064c8c) ./test() [0x8064c8c]
(0x805b774) ./test() [0x805b774]
(0xb6d72e37) /lib/i386-linux-gnu/libc.so.6(__libc_start_main+0xe7) [0xb6d72e37]
(0x8056181) ./test() [0x8056181]

errno = 0 (No error reported here)
OS error = ?


Sleeping until debugger attaches.
Please wait.
GNU gdb (Ubuntu/Linaro 7.2-1ubuntu11) 7.2
Copyright (C) 2010 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "i686-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Attaching to process 10674
Reading symbols from /home/fabio/sorgenti/0ad/trunk/binaries/system/test...done.
Couldn't get registers: Nessun processo corrispondente.
(gdb) 

Also for some reason I am no longer able to get proper backtrace since (probably) when the message window was added (look at the previous output).

I usually prefer running testing app with something like:

gdb -return-child-result -batch -ex run -ex 'thread apply all bt full' -ex kill -ex quit --args ./pyrogenesis

[Inazuma]

I was just wondering... I know the engine has been in development for years, however I can't help but feel you might benefit from switching to a ready-made engine. It would be stable, perform well and have nice bells and whistles. Above all, it would mean you can start focusing more on the game aspect.

Has this been considered?

[Ykkrosh]

fabio, on 05 November 2011 - 09:45 PM, said:

1) the profiler server starts when pressing F11 but can no longer be stopped?

Correct. This is probably all temporary though - I'll add some config variables and/or other ways to control the profiling.

Quote

the test fails

Fixed.

Inazuma, on 05 November 2011 - 11:38 PM, said:

I was just wondering... I know the engine has been in development for years, however I can't help but feel you might benefit from switching to a ready-made engine.

We've not seen any engines that would be suitable (open source, capable of supporting all the features we want, better than what we've currently got, etc). Even if there was one, it would generally be far more expensive in time and effort to adopt a radical change than to continue incrementally improving what we've already got (assuming what we've already got is capable of being extended to what we want, which I believe it is ).

[howlingflute]

Some really great new feature you are working on. Keep up the good work . I really like the save game feature and hope that the profiling tool acts as an asset in getting 0ad running faster. Awesome work.

[k776]

Had a chance to use the new profiler. The biggest time consumers per frame were:


* dispatch events (beween 500ms and 2000ms)
* sim update (about 500ms)
* swap buffer (about 80% of frames where 'dispatch events' and 'sim update' weren't run)

[fabio]

Ykkrosh, on 05 November 2011 - 11:57 PM, said:

Correct. This is probably all temporary though - I'll add some config variables and/or other ways to control the profiling.

OK, just a couple of suggestions: maybe you can also automatically start a browser (it's already done with the website button on welcome screen) when pressing the new profiler button (maybe different from the in game profiler, F12?) so one doesn't need to remember the path of the html.

Also the framerate (with SHIFT-F) varies too fast and is hardly readable. Maybe it should update less often, or eventually using a moving average.

[plumo]

The simupdate regularly freezes my game for a second or something. It jumps sometimes to 70 when i check with F11.

EDIT: when i try to open profiler2.html with google chrome dev version 17 AND internet explorer 9 it doesnt open. ""Failed to connect to server ("error") "". Should I click on profiler2.html while running 0 A.D. ? cause i ran it after shutting down the game.

Edited by plumo, 08 November 2011 - 10:26 AM.

[Android_]

Great job Philip, keep it going. (Just out of curiosity: What PhD programme did you do? )

Also I'm pleased to see that this time the Pledgie thing seems to be organized in a better and more transparent way. Last time it was more like "we need 3000 bucks to hire someone" and it took you quite some time to announce publicly who that would be in the first place. At least that was my impression; I'm sure though there was no major announcement that gave us the exact details.
This time we have a good announcement on the main page and Philip's excellent progress reports. Although I think that transparency could probably still be improved that makes for a much better incentive. (Which is why I donated as well .)

[feneur]

Android GRRR, on 08 November 2011 - 07:38 PM, said:

Great job Philip, keep it going. (Just out of curiosity: What PhD programme did you do? )

Also I'm pleased to see that this time the Pledgie thing seems to be organized in a better and more transparent way. Last time it was more like "we need 3000 bucks to hire someone" and it took you quite some time to announce publicly who that would be in the first place. At least that was my impression; I'm sure though there was no major announcement that gave us the exact details.
This time we have a good announcement on the main page and Philip's excellent progress reports. Although I think that transparency could probably still be improved that makes for a much better incentive. (Which is why I donated as well .)

Well, the trouble last time was that we couldn't be sure that Philip would be able to do the work, so it was more because of us not having any clear answers than anything else. We are aware that it could seem a bit weird though, so we're grateful people dared to donate anyway About more transparency now: Do you have any specific questions/suggestions for how to improve it?

[Android_]

Well you could reveal a bit more about how the whole idea of fundraising started, who decided who would get the job and how it was decided, how many hours 3000$ correspond to, anything like that. I'm more than happy with the outcomes you delivered (and that Philip was chosen!) it'd just be interesting to make the processes that led to these outcomes as transparent as possible. As I said though, I don't have any major concerns, I just thought it'd serve the cause as it might make people more confident about where their money goes and thus more willing to give. Maybe for future Pledgies.

Edited by Android GRRR, 09 November 2011 - 03:11 AM.

[plumo]

Android GRRR, on 09 November 2011 - 01:26 AM, said:

Well you could reveal a bit more about how the whole idea of fundraising started, who decided who would get the job and how it was decided, how many hours 3000$ correspond to, anything like that. I'm more than happy with the outcomes you delivered (and that Philip was chosen!) it'd just be interesting to make the processes that led to these outcomes as transparent as possible. As I said though, I don't have any major concerns, I just thought it'd serve the cause as it might make people more confident about where their money goes and thus more willing to give. Maybe for future Pledgies.

Overgrowth posts weekly alpha videos on moddb.com

I know this might be too much work for an open source game ( overgrowth videos make people pre-order = money ). But what about more posts and updates about this on moddb? It might raise awareness around the second pledgie campaign.

[Ykkrosh]

fabio, on 06 November 2011 - 08:13 AM, said:

maybe you can also automatically start a browser

Sounds like a good idea. Maybe I should change F11 to toggle a profiler menu screen, saying like "1: Hierarchical profiler. 2: Renderer stats. 3: Network stats. 4: Enable profiler2. 5: Open profiler2 visualiser.", so you can select what you want instead of hitting F11 lots of times to cycle through the modes, or something like that. (But I really need a better name than "profiler2" )

Quote

Also the framerate (with SHIFT-F) varies too fast and is hardly readable. Maybe it should update less often, or eventually using a moving average.

In theory it is a smoothed average (using an IIR filter), judging by the code. It does seem pretty terrible in practice, though - not sure why but it'd be good to fix

plumo, on 07 November 2011 - 08:39 PM, said:

The simupdate regularly freezes my game for a second or something.

Sounds like AI.

Quote

Should I click on profiler2.html while running 0 A.D. ? cause i ran it after shutting down the game.

Yes - it connects to the game via HTTP to download the current data, and doesn't store it on disk anywhere, so it won't work after shutting down. (Ideally it would be possible to save the profiling data to disk and load it later, or upload it and share with other developers, etc, but I haven't tried that yet.)

Android GRRR, on 08 November 2011 - 07:38 PM, said:

(Just out of curiosity: What PhD programme did you do? )

(It was some computer science stuff, to do with implementing routing protocols based on algebraic models.)

Quote

Last time it was more like "we need 3000 bucks to hire someone" and it took you quite some time to announce publicly who that would be in the first place.

Yeah, it was anticipated to be sooner but it took longer than hoped to finish my PhD, and nobody else argued strongly for doing the work themselves in the meantime, so it's been quite delayed (and we didn't want to publicly announce details until being fairly sure they were going to be correct)

Android GRRR, on 09 November 2011 - 01:26 AM, said:

Well you could reveal a bit more about how the whole idea of fundraising started

The history is basically that k776 suggested in #0ad-dev that I could work on the game for a year after finishing my PhD, given his good experiences with hiring a developer on Globulation 2, so he set up the Pledgie thing for $45K for a year's work (based on a roughly typical starting salary for software developers in the USA/UK/etc part of the world) for me or any other developer we'd think was appropriate, then the next day it was argued that $45K was insane so it was changed to $3000 for 1 month as a nice round figure, and that's about it . (It's less than I'd expect to get when starting a proper job, but (despite tax) more than I got as a PhD student, so it lets me wait and spend time on the game before getting a real life.)

Quote

how many hours 3000$ correspond to

160 hours (8 hours/day * 5 days/week * 4 weeks/month) though I'm not sure where that's stated explicitly.

plumo, on 09 November 2011 - 09:24 AM, said:

what about more posts and updates about this on moddb? It might raise awareness around the second pledgie campaign.

Yeah, I've been trying to get the hang of doing some videos and diagrams and explanations in this thread, but it's not an ideal place since few players will see it. Do you think these sort-of-daily progress reports would be suitable for ModDB, or would some changes to structure or style or content etc make them better? (and/or would some kind of new WFG developer blog be worthwhile for this? (Don't really want to clutter up the main news page, but ModDB seems slow at updates so maybe best not to use them exclusively.))

[Ykkrosh]

Day still-not-counted

Mostly finished playing around the GPU profiling code.

Committed it to SVN - if you want to try it (and your graphics drivers provide GL_ARB_timer_query, GL_EXT_timer_query, or GL_INTEL_performance_queries - most NVIDIA/AMD cards (with proprietary drivers if on Linux) should have the first two), you can launch the game, press F11 (which now enables the GPU profiler too), wait a while, then use profiler2.html, and it should have an extra row for the GPU data.

With an NVIDIA GPU (GTX 560 Ti) I get:



First coloured row is CPU, second (empty) row is some other thread, third row is GL_ARB_timer_query output, fourth is GL_EXT_timer_query. The difference is that the ARB one is aligned correctly relative to the CPU, whereas the EXT one isn't (it can only measure durations, it can't tell when the frame started rendering except by guessing), so the EXT one is not smoothly spaced and sometimes overlaps itself.

In the CPU row, the cyan box underneath "water reflections" represents a piece of code that's reading a bit of data back from the graphics drivers. That's a fast operation, but it looks like the NVIDIA drivers are taking it as an opportunity to delay the CPU - otherwise the CPU would continue generating frames faster than the GPU can render them, so the delay is just to stop the GPU falling too far behind.

Each frame is about 8 msec long, which corresponds to 120fps, which is plenty, and this is with 32x AA and 16x AF, so graphics performance isn't a problem on this kind of hardware.

With an Intel GPU (HD Graphics 3000) I get:



Average framerate is about 30fps, which isn't great, so optimisations for this kind of hardware would be worthwhile.

It doesn't have GL_*_timer_query but it does have GL_INTEL_performance_queries. That gives similar timing data as GL_EXT_timer_query (including the problem with frames overlapping each other because it can't tell when they start rendering). But it also gives a load of extra counters - the yellow box is a tooltip on the "patches" (terrain rendering) region of frame 265. It shows that e.g. we rendered 17876 triangles ("PrimitivesCount"), with 1.4 million pixels generated ("FragmentsRendered"), but about 10 million pixels of texture data were read ("SamplerPostFilteredTexels"), and the texture-reading hardware was busiest ("SamplerBusyTime: 0.986..."), which sounds like it might be the primary thing affecting the overall rendering performance. Would need to do a lot more work to fully understand and optimise rendering performance in this case, but at least it gives a bit of an idea about what to look into first.

Now I really ought to get back to some properly useful work...

[Android_]

Thanks for the info Philip, especially for that on the fundraising operation . Keep it up!

EDIT: I don't have any clue about performance issues, but it seems like the game eats a lot of CPU power. I have quite a new quadcore processor (Intel 2630QM) and yet my antivirus gives me a 'heavy CPU consumption' warning for pyrogenesis.exe. Just thought I'd let you know

Edited by Android GRRR, 09 November 2011 - 10:19 PM.

[feneur]

Android GRRR, on 09 November 2011 - 09:28 PM, said:

Thanks for the info Philip, especially for that on the fundraising operation . Keep it up!

EDIT: I don't have any clue about performance issues, but it seems like the game eats a lot of CPU power. I have quite a new quadcore processor (Intel 2630QM) and yet my antivirus gives me a 'heavy CPU consumption' warning for pyrogenesis.exe. Just thought I'd let you know

Philip can probably tell you more about the technical details, but in short the game uses as much CPU power as it can, I believe it is to give the highest framerate possible.

[Ykkrosh]

Yeah, there's no point buying expensive hardware if applications don't try to use it as much as they can to go as fast as they can . (The important thing is that they scale back to still work acceptably on older/cheaper hardware.)

[historic_bruno]

Ykkrosh, on 09 November 2011 - 02:09 PM, said:

In theory it is a smoothed average (using an IIR filter), judging by the code. It does seem pretty terrible in practice, though - not sure why but it'd be good to fix

I'll add a ticket for this