A New Render For Radiant (suggestion)

[OrbWeaver]

I did some extremely basic profiling of the XY renderer on a map with 192 AI in it, using the new ScopedDebugTimer class.

 

[ScopedDebugTimer] "XYWnd::draw()" in 0.0391119 (25.5677 FPS)
[ScopedDebugTimer] "  Scene_Render()" in 0.0251 (39.8406 FPS)
[ScopedDebugTimer] "XYRenderer::render()" in 0.00648403 (154.225 FPS)
[ScopedDebugTimer] "  renderer.render()" in 0.00655317 (152.598 FPS)
[ScopedDebugTimer] "XYWnd::draw()" in 0.0395551 (25.2812 FPS)
[ScopedDebugTimer] "  Scene_Render()" in 0.026062 (38.37 FPS)
[ScopedDebugTimer] "XYRenderer::render()" in 0.00578904 (172.74 FPS)
[ScopedDebugTimer] "  renderer.render()" in 0.00584793 (171.001 FPS)
[ScopedDebugTimer] "XYWnd::draw()" in 0.039279 (25.4589 FPS)
[ScopedDebugTimer] "  Scene_Render()" in 0.0282099 (35.4485 FPS)
[ScopedDebugTimer] "XYRenderer::render()" in 0.00601792 (166.17 FPS)
[ScopedDebugTimer] "  renderer.render()" in 0.006078 (164.528 FPS)
[ScopedDebugTimer] "XYWnd::draw()" in 0.0415812 (24.0494 FPS)
[ScopedDebugTimer] "  Scene_Render()" in 0.0312378 (32.0125 FPS)
[ScopedDebugTimer] "XYRenderer::render()" in 0.0105901 (94.428 FPS)
[ScopedDebugTimer] "  renderer.render()" in 0.0106549 (93.8533 FPS)
[ScopedDebugTimer] "XYWnd::draw()" in 0.0455971 (21.9312 FPS)
[ScopedDebugTimer] "  Scene_Render()" in 0.0249441 (40.0897 FPS)
[ScopedDebugTimer] "XYRenderer::render()" in 0.00563598 (177.432 FPS)
[ScopedDebugTimer] "  renderer.render()" in 0.00569987 (175.443 FPS)
[ScopedDebugTimer] "XYWnd::draw()" in 0.037251 (26.8449 FPS)
[ScopedDebugTimer] "  Scene_Render()" in 0.0304759 (32.8129 FPS)
[ScopedDebugTimer] "XYRenderer::render()" in 0.00621605 (160.874 FPS)
[ScopedDebugTimer] "  renderer.render()" in 0.006284 (159.134 FPS)
[ScopedDebugTimer] "XYWnd::draw()" in 0.0441101 (22.6706 FPS)
[ScopedDebugTimer] "  Scene_Render()" in 0.031491 (31.7551 FPS)
[ScopedDebugTimer] "XYRenderer::render()" in 0.00569606 (175.56 FPS)
[ScopedDebugTimer] "  renderer.render()" in 0.00575805 (173.67 FPS)
[ScopedDebugTimer] "XYWnd::draw()" in 0.045018 (22.2134 FPS)
[ScopedDebugTimer] "  Scene_Render()" in 0.025492 (39.2281 FPS)
[ScopedDebugTimer] "XYRenderer::render()" in 0.00598717 (167.024 FPS)
[ScopedDebugTimer] "  renderer.render()" in 0.00604701 (165.371 FPS)
[ScopedDebugTimer] "XYWnd::draw()" in 0.038286 (26.1192 FPS)
[ScopedDebugTimer] "  Scene_Render()" in 0.0350919 (28.4966 FPS)
[ScopedDebugTimer] "XYRenderer::render()" in 0.00571513 (174.974 FPS)
[ScopedDebugTimer] "  renderer.render()" in 0.00577497 (173.161 FPS)

 

Scene_Render() is the function which controls the traversal of the scenegraph, whereas XYRenderer::render() just calls the GlobalShaderCache() to render all of the geometry that has been passed to it.

 

As I suspected, it seems that the front-end of the renderer (Scene_Render()) is by far the bottleneck in this rendering operation. Display Lists are being used, so the actual render is very quick -- it is just finding the objects to render which takes the time.

[greebo]

It would be interesting how the scaling behaviour of the various scenegraph object types is, i.e. what happens when you put 1000 brushes into the map and what happens when 2000 brushes are in there. Maybe the front-end render methods of brushes are slower than the model front-ends?

[OrbWeaver]

With 1024 square brushes:

 

[ScopedDebugTimer] "XYWnd::draw()" in 0.022717 (44.0199 FPS)
[ScopedDebugTimer] "  Scene_Render()" in 0.0256801 (38.9407 FPS)
[ScopedDebugTimer] "XYRenderer::render()" in 0.00160789 (621.931 FPS)
[ScopedDebugTimer] "  renderer.render()" in 0.00167108 (598.417 FPS)
[ScopedDebugTimer] "XYWnd::draw()" in 0.0281289 (35.5507 FPS)
[ScopedDebugTimer] "  Scene_Render()" in 0.0196831 (50.8049 FPS)
[ScopedDebugTimer] "XYRenderer::render()" in 0.00154901 (645.575 FPS)
[ScopedDebugTimer] "  renderer.render()" in 0.00161099 (620.735 FPS)
[ScopedDebugTimer] "XYWnd::draw()" in 0.0221789 (45.0879 FPS)
[ScopedDebugTimer] "  Scene_Render()" in 0.0258369 (38.7043 FPS)
[ScopedDebugTimer] "XYRenderer::render()" in 0.00161004 (621.102 FPS)
[ScopedDebugTimer] "  renderer.render()" in 0.00167108 (598.417 FPS)
[ScopedDebugTimer] "XYWnd::draw()" in 0.0283082 (35.3255 FPS)
[ScopedDebugTimer] "  Scene_Render()" in 0.0196168 (50.9766 FPS)
[ScopedDebugTimer] "XYRenderer::render()" in 0.00154901 (645.575 FPS)
[ScopedDebugTimer] "  renderer.render()" in 0.00160599 (622.67 FPS)
[ScopedDebugTimer] "XYWnd::draw()" in 0.0219941 (45.4667 FPS)
[ScopedDebugTimer] "  Scene_Render()" in 0.0210772 (47.4447 FPS)
[ScopedDebugTimer] "XYRenderer::render()" in 0.00165796 (603.15 FPS)
[ScopedDebugTimer] "  renderer.render()" in 0.00170994 (584.817 FPS)
[ScopedDebugTimer] "XYWnd::draw()" in 0.0235262 (42.5058 FPS)
[ScopedDebugTimer] "  Scene_Render()" in 0.032896 (30.3988 FPS)
[ScopedDebugTimer] "XYRenderer::render()" in 0.0236788 (42.2319 FPS)
[ScopedDebugTimer] "  renderer.render()" in 0.0237401 (42.1229 FPS)

 

With 256 func_statics each containing a single square brush:

 

[ScopedDebugTimer] "XYWnd::draw()" in 0.0508871 (19.6513 FPS)
[ScopedDebugTimer] "  Scene_Render()" in 0.049263 (20.2992 FPS)
[ScopedDebugTimer] "XYRenderer::render()" in 0.000655174 (1526.31 FPS)
[ScopedDebugTimer] "  renderer.render()" in 0.000710964 (1406.54 FPS)
[ScopedDebugTimer] "XYWnd::draw()" in 0.05071 (19.72 FPS)
[ScopedDebugTimer] "  Scene_Render()" in 0.049578 (20.1703 FPS)
[ScopedDebugTimer] "XYRenderer::render()" in 0.000849962 (1176.52 FPS)
[ScopedDebugTimer] "  renderer.render()" in 0.000904083 (1106.09 FPS)
[ScopedDebugTimer] "XYWnd::draw()" in 0.051317 (19.4867 FPS)
[ScopedDebugTimer] "  Scene_Render()" in 0.0492821 (20.2914 FPS)
[ScopedDebugTimer] "XYRenderer::render()" in 0.000583887 (1712.66 FPS)
[ScopedDebugTimer] "  renderer.render()" in 0.000634909 (1575.03 FPS)
[ScopedDebugTimer] "XYWnd::draw()" in 0.050663 (19.7383 FPS)
[ScopedDebugTimer] "  Scene_Render()" in 0.049422 (20.2339 FPS)
[ScopedDebugTimer] "XYRenderer::render()" in 0.000597 (1675.04 FPS)
[ScopedDebugTimer] "  renderer.render()" in 0.000647068 (1545.43 FPS)
[ScopedDebugTimer] "XYWnd::draw()" in 0.0507898 (19.689 FPS)
[ScopedDebugTimer] "  Scene_Render()" in 0.0488389 (20.4755 FPS)
[ScopedDebugTimer] "XYRenderer::render()" in 0.000662088 (1510.37 FPS)
[ScopedDebugTimer] "  renderer.render()" in 0.000715971 (1396.7 FPS)
[ScopedDebugTimer] "XYWnd::draw()" in 0.0503101 (19.8767 FPS)
[ScopedDebugTimer] "  Scene_Render()" in 0.0501909 (19.9239 FPS)
[ScopedDebugTimer] "XYRenderer::render()" in 0.000672102 (1487.87 FPS)
[ScopedDebugTimer] "  renderer.render()" in 0.000731945 (1366.22 FPS)
[ScopedDebugTimer] "XYWnd::draw()" in 0.051646 (19.3626 FPS)
[ScopedDebugTimer] "  Scene_Render()" in 0.04829 (20.7082 FPS)
[ScopedDebugTimer] "XYRenderer::render()" in 0.000692129 (1444.82 FPS)
[ScopedDebugTimer] "  renderer.render()" in 0.000746012 (1340.46 FPS)
[ScopedDebugTimer] "XYWnd::draw()" in 0.049741 (20.1041 FPS)
[ScopedDebugTimer] "  Scene_Render()" in 0.0510459 (19.5902 FPS)
[ScopedDebugTimer] "XYRenderer::render()" in 0.000609159 (1641.61 FPS)
[ScopedDebugTimer] "  renderer.render()" in 0.000666142 (1501.18 FPS)

 

So yes, it looks like traversing entities is the real bottleneck.

[OrbWeaver]

Looks like this is the culprit so far:

 

void CompiledGraph::traverse_subgraph(const Walker& walker, InstanceMap::iterator i) {

ScopedDebugTimer t("  traverse_subgraph()", true);

std::stack<InstanceMap::iterator> stack;
if (i != m_instances.end()) {
	// Initialise the start size using the path depth of the given iterator
	const std::size_t startSize = i->first.get().size();

	do {
		if (i != m_instances.end() && 
			stack.size() < (i->first.get().size() - startSize + 1))
		{
			stack.push(i);
			++i;
			if (!pre(walker, stack.top())) {
				// Walker's pre() return false, skip subgraph
				while (i != m_instances.end() && 
					   stack.size() < (i->first.get().size() - startSize + 1))
				{
					++i;
				}
			}
		}
		else {
			post(walker, stack.top());
			stack.pop();
		}
	} while (!stack.empty());
}
}

 

I don't really understand all that is going on in this function, but it is possible that the repeated calls to stack::size() are slowing things down, since std::vector::size() is actually O(n) in the length of the vector (it counts the elements each time).

[greebo]

Interesting. Be aware that both the func_static and the child brush will be queried to render, so in fact there are 512 objects being rendered in the second test. Also, the scenegraph structure is different (1 child per entity, 256 entities) to the first one (1024 child objects of 1 entity), where less scenegraph overhead is happening.

 

What happens if you try to render two func_statics with 128 or 256 child brushes each?

 

edit (just saw your post): This is the actual traversal function, which calls the render walker, it doesn't surprise me that this takes the same CPU time as the rendering itself (this is the front-end rendering after all). However, if the std::vector::size() call can be cached and saves time, we should give that a try.

[OrbWeaver]

edit (just saw your post): This is the actual traversal function, which calls the render walker, it doesn't surprise me that this takes the same CPU time as the rendering itself (this is the front-end rendering after all). However, if the std::vector::size() call can be cached and saves time, we should give that a try.

 

The actual call to walker::pre() takes hardly any time though:

 

[ScopedDebugTimer] "   calling actual walker::pre()" in 5.91278e-05 (16912.5 FPS)
[ScopedDebugTimer] "   calling actual walker::pre()" in 0.00227618 (439.332 FPS)
[ScopedDebugTimer] "   calling actual walker::pre()" in 4.88758e-05 (20460 FPS)
[ScopedDebugTimer] "   calling actual walker::pre()" in 0.00026989 (3705.22 FPS)
[ScopedDebugTimer] "   calling actual walker::pre()" in 4.1008e-05 (24385.5 FPS)
[ScopedDebugTimer] "   calling actual walker::pre()" in 0.000340939 (2933.08 FPS)
[ScopedDebugTimer] "   calling actual walker::pre()" in 5.29289e-05 (18893.3 FPS)

 

although it is interesting that it flips between two different speeds, which probably corresponds to the two different stack depths.

 

Basicallly I think this algorithm and data structure is entirely bogus -- it is trying to represent an N-tree using a map of NodeConstReference->Instance pairs, and is "traversing" them just by comparing stack depths and skipping over stuff by incrementing the iterator. If the data represents a tree, it should be stored in a tree structure.

 

The very fact that this function is difficult to understand gives a strong clue that the design is wrong.

[greebo]

I can look into refactoring the scenegraph, if you want me to and if you don't want to do it yourself. I've gained some insight while refactoring the scene::Node and scene::Path paths, so I think I'm capable of doing that. (The refactor will a pain in the ass nonetheless, regardless who is doing it.)

[OrbWeaver]

I certainly won't get in your way if you want to do the refactoring, but we should pool ideas first and make sure we have a good design before going ahead with it, particularly if performance is the main driver behind the task.

 

Some example output from Gprof on the 192 AI map:

 

Each sample counts as 0.01 seconds.
 %   cumulative   self			  self	 total		   
time   seconds   seconds	calls  ms/call  ms/call  name	
 7.48	  0.78	 0.78							 call_gmon_start
 5.08	  1.31	 0.53  2964778	 0.00	 0.00  boost::detail::atomic_increment(int*)
 3.84	  1.71	 0.40  3104449	 0.00	 0.00  boost::detail::atomic_exchange_and_add(int*, int)
 3.79	  2.10	 0.40  4568179	 0.00	 0.00  double BasicVector3<double>::dot<double>(BasicVector3<double> const&) const
 2.78	  2.40	 0.29   758622	 0.00	 0.00  BasicVector3<double> matrix4_transformed_point<double>(Matrix4 const&, BasicVector3<double> const&)
 2.49	  2.65	 0.26   190509	 0.00	 0.01  ForEachVisible<RenderHighlighted>::pre(scene::Path const&, scene::Instance&) const
 1.63	  2.83	 0.17  1977171	 0.00	 0.00  __gnu_cxx::__normal_iterator<char const*, std::string>::operator*() const
 1.58	  2.99	 0.17  4549479	 0.00	 0.00  plane_contains_oriented_aabb(Plane3 const&, AABB const&, Matrix4 const&)
 1.44	  3.14	 0.15   758430	 0.00	 0.00  frustum_intersects_transformed_aabb(Frustum const&, AABB const&, Matrix4 const&)
 1.44	  3.29	 0.15	  503	 0.30	 0.85  OpenGLStateBucket::flushRenderables(OpenGLState&, unsigned int, BasicVector3<double> const&)
 1.29	  3.42	 0.14   164817	 0.00	 0.00  bool __gnu_cxx::operator!=<char const*, std::string>(__gnu_cxx::__normal_iterator<char const*, std::string> const&, __gnu_cxx::__normal_iterator<char const*, std::string> const&)
 1.25	  3.56	 0.13 19259200	 0.00	 0.00  __gnu_cxx::__normal_iterator<char const*, std::string>::base() const
 1.25	  3.69	 0.13	94533	 0.00	 0.00  matrix4_affine_equal(Matrix4 const&, Matrix4 const&)
 1.25	  3.81	 0.13	  889	 0.15	 0.88  CompiledGraph::traverse_subgraph(scene::Graph::Walker const&, std::_Rb_tree_iterator<std::pair<ConstReference<scene::Path> const, scene::Instance*> >)
 1.05	  3.92	 0.11  1894832	 0.00	 0.00  std::vector<XYRenderer::state_type, std::allocator<XYRenderer::state_type> >::back()
 1.05	  4.04	 0.11   757844	 0.00	 0.00  OpenGLShader::addRenderable(OpenGLRenderable const&, Matrix4 const&, LightList const*)
 0.96	  4.13	 0.10   911010	 0.00	 0.00  std::vector<boost::shared_ptr<scene::INode>, std::allocator<boost::shared_ptr<scene::INode> > >::begin() const
 0.96	  4.24	 0.10   224312	 0.00	 0.00  OpenGLStateBucket::applyState(OpenGLState&, unsigned int)
 0.86	  4.33	 0.09 11562780	 0.00	 0.00  Matrix4::operator double const*() const
 0.77	  4.41	 0.08  1393037	 0.00	 0.00  std::vector<boost::shared_ptr<scene::INode>, std::allocator<boost::shared_ptr<scene::INode> > >::end() const
 0.77	  4.49	 0.08   190056	 0.00	 0.00  RenderHighlighted::pre(scene::Path const&, scene::Instance&, EnumeratedValue<VolumeIntersection>) const
 0.77	  4.57	 0.08		5	16.00	29.76  __gnu_cxx::__normal_iterator<char const*, std::string>::operator++(int)
 0.67	  4.63	 0.07  6247734	 0.00	 0.00  __gnu_cxx::__normal_iterator<char const*, std::string>::__normal_iterator(char const* const&)
 0.67	  4.71	 0.07  4549479	 0.00	 0.00  plane_distance_to_point(Plane3 const&, BasicVector3<double> const&)
 0.67	  4.78	 0.07		1	70.00   506.60  xml::Document::findXPath(std::string const&) const
 0.62	  4.84	 0.07   758430	 0.00	 0.00  debug_count_oriented_bbox()
 0.62	  4.91	 0.07   190895	 0.00	 0.00  boost::shared_ptr<scene::INode>::operator->() const
 0.58	  4.96	 0.06  1894832	 0.00	 0.00  __gnu_cxx::__normal_iterator<XYRenderer::state_type*, std::vector<XYRenderer::state_type, std::allocator<XYRenderer::state_type> > >::operator-(int const&) const
 0.58	  5.03	 0.06   758430	 0.00	 0.00  void matrix4_transform_point<double>(Matrix4 const&, BasicVector3<double>&)
 0.58	  5.08	 0.06   197862	 0.00	 0.00  boost::shared_ptr<Shader>::~shared_ptr()
 0.58	  5.14	 0.06   191558	 0.00	 0.00  boost::shared_ptr<Shader>::shared_ptr(boost::shared_ptr<Shader> const&)
 0.58	  5.21	 0.06	95245	 0.00	 0.00  SingletonModuleRef<FilterSystem>::getTable()
 0.58	  5.26	 0.06	94779	 0.00	 0.00  OpenGLShaderCache::evaluateChanged()

 

Some of the expected rendering code is there, but there is also a surprising amount of maths code (something to do with view frustrum culling) and it looks like the shared_ptr<> implementation is taking up the largest slice of the time. Maybe for certain sections of the scenegraph it would be necessary to access the raw pointers directly.

[greebo]

Why would the shared_ptr destructor be called so often? Are the shader pointers passed by copy to the renderer?

 

Also, I do notice the xml::Document::findXPath call which seems to take 500 ms (?). This is a strong argument for caching XMLRegistry values as local class members. Good thing I already did that with many values, but obviously the Registry is called during rendering.

 

Is there a difference between release and debug mode in terms of shared_ptr accesses? I know that the operator-> has an assertion in it, can this be turned off?

[OrbWeaver]

Why would the shared_ptr destructor be called so often? Are the shader pointers passed by copy to the renderer?

 

Yes, the culprit seemed to be PushState() and PopState() in XYRenderer, which were manipulating a vector of structs each of which contained a ShaderPtr. I have changed this to a raw pointer for performance, as well as reserving 8 slots in the initial vector to avoid reallocation delays.

 

Of course it is hard to tell whether this made a significant difference, because even with a profiler you never get the same result twice. It SEEMS like the amount of time spent in these functions is relatively lower and SEEMS like there might be a possible performance improvement, but no miracles.

 

Also, I do notice the xml::Document::findXPath call which seems to take 500 ms (?). This is a strong argument for caching XMLRegistry values as local class members. Good thing I already did that with many values, but obviously the Registry is called during rendering.

 

I don't think this is anything to do with rendering: you have to profile a whole session, not just a particular function. Starting up and loading the map took a considerable amount of time which shows up in the profile results.

[greebo]

Ah, ok, I didn't have any idea how this profiling works. I thought you could hit a hotkey for starting and stopping the profiling...

 

The FilterSystem calls seem to take some amount of time as well, just to retrieve the pointer?

[OrbWeaver]

You are on the right track with the FilterSystem, the profiler reveals that this code in ForEachVisible<> is a performance issue:

 

// Examine the entity class for its filter status. If it is filtered, 
// use the c_volumeOutside state to ensure it is not rendered.
Entity* entity = Node_getEntity(path.top());
if (entity) {
IEntityClassConstPtr eclass = entity->getEntityClass();
std::string name = eclass->getName();
if (!GlobalFilterSystem().isVisible("entityclass", name)) {
	visible = c_volumeOutside;
}
}

 

I always thought this might be an issue, because of the visibility test, but it seems that the copying of IEntityClassConstPtr is a problem, as is the call to Node_getEntity() which involves a dynamic_pointer_cast.

 

I may have to rethink the filter system somewhat, for example by having the filter system itself actively traverse the scene graph and set a "visibility bit" in each of the scene::Instance objects, rather than having each instance check its entity class during rendering.

[greebo]

I may have to rethink the filter system somewhat, for example by having the filter system itself actively traverse the scene graph and set a "visibility bit" in each of the scene::Instance objects, rather than having each instance check its entity class during rendering.

That's what I was about to suggest. We should take the "state" approach (objects stay filtered until being told otherwise) rather than the "dynamic" approach (check each frame if filtered).

[OrbWeaver]

Well that's done, and although there is no great leap forward in performance, at least the Boost overheads are creeping down the profile graph and more prominence is being given to mathematical functions.

 

I think the next step will be to look at view frustum culling in the XY view, which seems to be giving a lot of time to vector and matrix calculations. For an orthographic 2D view, there is no need to have a full 3D view frustum with front and back planes, it would be quicker to simply calculate the AABB intersection by comparing the AABB extents with the viewport extents in two dimensions.

[greebo]

Does the current culling differentiate between Orthoviews and Camviews? I'd guess they are handled in a unified way, but I haven't looked into that.

[OrbWeaver]

No, that is precisely the problem. The class View is the implementation of VolumeTest used in both situations, and it expects to provide a full 3D view frustum.

[greebo]

I think it would be sufficient to add another implementation of VolumeTest or derive publically from the View class. Every Cullable instance is calling VolumeTest::TestAABB(), TestLineStrip(), TestWhatever().

 

In View::TestAABB() (which is called by the BrushInstance for example) the helper function frustum_test_aabb is called, which could be replaced by a simpler AABB intersection for the Orthoviews. Then the members View XYWnd::m_view could be substituted by the specialised VolumeTest implementation. This should have quite some impact.

[OrbWeaver]

That's exactly what I was planning: create a new class OrthoViewVolume which derives from VolumeTest but implements TestAABB() with a simple subtraction-based 2D intersection rather than using totally unnecessary vector dot products.

 

The latest profiling shows that BasicVector3::dot() is by far the most time-consuming function in the session, so this should make a difference.

[greebo]

Sounds good.

 

Another optimisation that comes to my mind is to make every scene::Instance derive from Cullable, so that the dynamic_cast can be dropped (which is potentially slow).

 

Most instances are cullable, we just have to think about the "meta"-instances like the MapRootNode (which would have always to return a "c_VolumePartial" as result of intersectVolume(), which in turn triggers a intersectVolume() test on all its children.

[OrbWeaver]

I'm not totally sure that Cullable is actually being used here -- from what I remember, the ForEachVisible walker just calls Instance::worldAABB() on each instance and passes this AABB to View::TestAABB(), which performs the intersection test using vector arithmetic without reference to the Cullable interface's methods.

 

Either way, I haven't yet seen any issues with casting to Cullable on the profile output, I think that the next "slugs" after View::TestAABB() are in the render backend.