Render of 3D image is very slow #98190

New Issue

a · 2022-05-17T11:14:42+02:00

a commented

2022-05-17 11:14:42 +02:00

System Information
Operating system: Windows 8.1
Graphics card: Intel(R) HD Graphics 4400, 4.3.0 - Build 10.18.14.4264

Blender Version
Broken: 3.3.0 caused by 80859a6cb2
Worked: 3.1.0 onwards

Render of simple 3d image takes excessive time when sequencer is in pipeline but sequencer has no strips. While rendering slowly, the process size grows and Blender UI stops responding.

Exact steps for others to reproduce the error

Default startup (Eevee, Default Cube scene etc)
Change Editor Type to '3D Viewport'
Drag to add a new window, set to Video Sequencer
Confirm sequencer is empty
Confirm Post Processing 'Compositing' checked, 'Sequencer' checked
Render -> Render Image
Observe the default cube is rendered after approx 1 minute (depending on hardware)
Uncheck Post Processing > Sequencer so that VSE is no longer in the pipeline
Render -> Render Image
Observe the default cube is rendered after approx 1 second (depending on hardware)

Note:

When sequencer is in pipeline and VSE has at least one strip then Render Image completes in approx 1 second, displaying the expected strip.

When the sequencer is empty, but is in the pipeline then should the rendered image also be empty?

Supporting Video

https://youtu.be/A_dU0KY9miQ

**System Information** Operating system: Windows 8.1 Graphics card: Intel(R) HD Graphics 4400, 4.3.0 - Build 10.18.14.4264 **Blender Version** Broken: 3.3.0 caused by 80859a6cb2 Worked: 3.1.0 onwards Render of simple 3d image takes excessive time when sequencer is in pipeline but sequencer has no strips. While rendering slowly, the process size grows and Blender UI stops responding. **Exact steps for others to reproduce the error** 1. Default startup (Eevee, Default Cube scene etc) 2. Change Editor Type to '3D Viewport' 3. Drag to add a new window, set to Video Sequencer 4. Confirm sequencer is empty 5. Confirm Post Processing 'Compositing' checked, 'Sequencer' checked 6. Render -> Render Image 7. Observe the default cube is rendered after approx 1 minute (depending on hardware) 8. Uncheck Post Processing > Sequencer so that VSE is no longer in the pipeline 9. Render -> Render Image 10. Observe the default cube is rendered after approx 1 second (depending on hardware) Note: When sequencer is in pipeline and VSE has at least one strip then Render Image completes in approx 1 second, displaying the expected strip. When the sequencer is empty, but is in the pipeline then should the rendered image also be empty? **Supporting Video** https://youtu.be/A_dU0KY9miQ

a commented

2022-05-17 11:14:42 +02:00

Added subscriber: @blenderbug12345

blender-admin commented

2022-05-17 11:14:42 +02:00

#98710 was marked as duplicate of this issue

a changed title from ~~Render of 3D image is very slow when and EMPTY VSE is in the Post Processing pipeline.~~ to Render of 3D image is very slow when an EMPTY VSE is in the Post Processing pipeline.

2022-05-17 11:15:01 +02:00

Philipp Oeser commented

2022-05-17 12:18:47 +02:00

Added subscriber: @lichtwerk

Philipp Oeser commented

2022-05-17 12:18:47 +02:00

Changed status from 'Needs Triage' to: 'Needs User Info'

Philipp Oeser commented

2022-05-17 12:18:47 +02:00

Cannot reproduce here

**System Information**
Operating system: Linux-5.13.0-0.rc6.45.fc35.x86_64-x86_64-with-glibc2.34.9000 64 Bits
Graphics card: NVIDIA GeForce GTX 970M/PCIe/SSE2 NVIDIA Corporation 4.5.0 NVIDIA 495.44
version: 3.3.0 Alpha, branch: master, commit date: 2022-05-17 09:31, hash: `rBf9ed31b15d7a`

So 3.1.2 was working for you?
Is 3.2beta from https://builder.blender.org/download/daily/ also affected?
Please try with File → Defaults → Load Factory Settings to see if you still can reproduce this issue.

Cannot reproduce here ``` **System Information** Operating system: Linux-5.13.0-0.rc6.45.fc35.x86_64-x86_64-with-glibc2.34.9000 64 Bits Graphics card: NVIDIA GeForce GTX 970M/PCIe/SSE2 NVIDIA Corporation 4.5.0 NVIDIA 495.44 version: 3.3.0 Alpha, branch: master, commit date: 2022-05-17 09:31, hash: `rBf9ed31b15d7a` ``` - So 3.1.2 was working for you? - Is 3.2beta from https://builder.blender.org/download/daily/ also affected? - Please try with File → Defaults → Load Factory Settings to see if you still can reproduce this issue.

Pratik Borhade commented

2022-05-17 12:58:56 +02:00

Added subscriber: @PratikPB2123

Pratik Borhade commented

2022-05-17 12:58:56 +02:00

cannot reproduce either- 3.3, 8c4bd02b067a

Operating system : Windows-10-10.0.18362-SP0 64 Bits
Graphics card : AMD Radeon(TM) 535 ATI Technologies .```

cannot reproduce either- 3.3, `8c4bd02b067a` ```System Information Operating system : Windows-10-10.0.18362-SP0 64 Bits Graphics card : AMD Radeon(TM) 535 ATI Technologies .```

a commented

2022-05-17 14:05:57 +02:00

I've added a video of the problem here: https://youtu.be/A_dU0KY9miQ

a commented

2022-05-17 14:15:51 +02:00

The problem is found in blender-3.2.0-beta+v32.a2dacefb4636-windows.amd64-release also.

Problem still present with File .. Defaults .. Load Factory Settings

I don't have a full set of dailys to play with at the moment, but it looks like some change made between apr 22/29th

apr.29 blender-3.2.0-alpha+master.a7db7f88b067-windows.amd64-release BUG
apr.22 blender-3.2.0-alpha+master.179100c02126-windows.amd64-release OK

The problem is found in blender-3.2.0-beta+v32.a2dacefb4636-windows.amd64-release also. Problem still present with File .. Defaults .. Load Factory Settings I don't have a full set of dailys to play with at the moment, but it looks like some change made between apr 22/29th apr.29 blender-3.2.0-alpha+master.a7db7f88b067-windows.amd64-release BUG apr.22 blender-3.2.0-alpha+master.179100c02126-windows.amd64-release OK

Philipp Oeser commented

2022-05-17 14:27:14 +02:00

Still cannot repro.

Worked: 3.1.0 onwards

3.1.2 was fine, right?

Still cannot repro. > Worked: 3.1.0 onwards 3.1.2 was fine, right?

a commented

2022-05-17 14:35:17 +02:00

3.1.2 is ok, although it renders the 3d scene even when the empty VSE is in the pipeline, but at least it's fast.

mar.31 blender-3.1.2-candidate+v31.2cfca7d9101d-windows.amd64-release OK

3.1.2 is ok, although it renders the 3d scene even when the empty VSE is in the pipeline, but at least it's fast. mar.31 blender-3.1.2-candidate+v31.2cfca7d9101d-windows.amd64-release OK

a commented

2022-05-17 15:08:42 +02:00

Looking at available dailys I see the slow behaviour first happen on apr.29

apr.29 blender-3.2.0-alpha+master.a1b21a350383-windows.amd64-release SLOW
apr.28 blender-3.2.0-alpha+master.308a12ac647d-windows.amd64-release OK

note that some builds earlier than apr.29 seem to have a flashing screen while rendering quickly

Looking at available dailys I see the slow behaviour first happen on apr.29 apr.29 blender-3.2.0-alpha+master.a1b21a350383-windows.amd64-release SLOW apr.28 blender-3.2.0-alpha+master.308a12ac647d-windows.amd64-release OK note that some builds earlier than apr.29 seem to have a flashing screen while rendering quickly

Germano Cavalcante commented

2022-05-17 17:05:30 +02:00

Added subscriber: @mano-wii

Germano Cavalcante commented

2022-05-17 17:05:30 +02:00

I cannot reproduce the problem.
Tested on:

OS: Windows 11 64 Bits
CPU: AMD Ryzen 1800x
GPU: Radeon 480

April 29th was when the libraries were updated (See {rBL62897})
Maybe some library doesn't work well in hardware or driver (Windows 8 is starting to get outdated)

Please double-check if the drivers are up to date and the hardware meets Blender's requirements: https://www.blender.org/download/requirements
To upgrade to the latest driver, see here for more information: https://docs.blender.org/manual/en/dev/troubleshooting/gpu/index.html

Also can you check if any slowdowns are also observed when rendering with Eevee?

I cannot reproduce the problem. Tested on: ``` OS: Windows 11 64 Bits CPU: AMD Ryzen 1800x GPU: Radeon 480 ``` April 29th was when the libraries were updated (See {rBL62897}) Maybe some library doesn't work well in hardware or driver (Windows 8 is starting to get outdated) Please double-check if the drivers are up to date and the hardware meets Blender's requirements: https://www.blender.org/download/requirements To upgrade to the latest driver, see here for more information: https://docs.blender.org/manual/en/dev/troubleshooting/gpu/index.html Also can you check if any slowdowns are also observed when rendering with Eevee?

a commented

2022-05-18 00:13:37 +02:00

I took a closer look at how my system was set up.

Drivers are as new as I can get them to be for a windows 8.1 build.

I have NVIDIA Control Panel which lets you set up a profile for different applications. And blender.exe was running with the default Integrated graphics card for 3d operations. I think I set it up like this because I was getting overheating issues last summer, and then... I forgot about it. I've been using VSE exclusively for a few months and there's not much of a performance problem there because VSE doesn't seem to use the GPU, so again I didn't notice.

I got a copy of 'Process Explorer' so I could see what the GPU was actually doing on my windows 8.1 laptop and I think I understand it a little better.

On the latest alpha, with EEVEE as the render engine and when following the steps to reproduce the error:

I'm seeing the performance hit, when rendering 3d objects and when the NVIDIA 3d profile is set to Integrated graphics.
When I switch the profile to 'High Performance NVIDIA Processor' then the rendering is moved to the GPU and is much faster.

On 3.1.0, with EEVEE:

I don't see a performance hit when rendering 3d objects, even when the NVIDIA 3d profile is set to Integrated graphics

So:

it looks like the CPU-only rendering of 3d scenes has got worse in the alpha

Since I can just turn on the GPU profile for blender.exe this becomes less of a problem for me.

I traced the slow-down in the alpha code as far as this call, which takes > 1 minute to return and soaks the CPU. There's nothing going on with the GPU until a small spike then the final image appears in the Render Result viewer.

engine.c:engine_render_view_layer(...)
...
engine->type->render(engine, engine->depsgraph);
...

I took a closer look at how my system was set up. Drivers are as new as I can get them to be for a windows 8.1 build. I have NVIDIA Control Panel which lets you set up a profile for different applications. And blender.exe was running with the default Integrated graphics card for 3d operations. I think I set it up like this because I was getting overheating issues last summer, and then... I forgot about it. I've been using VSE exclusively for a few months and there's not much of a performance problem there because VSE doesn't seem to use the GPU, so again I didn't notice. I got a copy of 'Process Explorer' so I could see what the GPU was actually doing on my windows 8.1 laptop and I think I understand it a little better. On the latest alpha, with EEVEE as the render engine and when following the steps to reproduce the error: - I'm seeing the performance hit, when rendering 3d objects and when the NVIDIA 3d profile is set to Integrated graphics. - When I switch the profile to 'High Performance NVIDIA Processor' then the rendering is moved to the GPU and is much faster. On 3.1.0, with EEVEE: - I don't see a performance hit when rendering 3d objects, even when the NVIDIA 3d profile is set to Integrated graphics So: - it looks like the CPU-only rendering of 3d scenes has got worse in the alpha Since I can just turn on the GPU profile for blender.exe this becomes less of a problem for me. I traced the slow-down in the alpha code as far as this call, which takes > 1 minute to return and soaks the CPU. There's nothing going on with the GPU until a small spike then the final image appears in the Render Result viewer. ``` engine.c:engine_render_view_layer(...) ... engine->type->render(engine, engine->depsgraph); ... ```

Raimund Klink commented

2022-05-18 12:14:40 +02:00

Added subscriber: @Raimund58

Raimund Klink commented

2022-05-18 12:14:40 +02:00

What CPU model do you have? Or attach the system info. (Blender->Help->Save System Info)

a commented

2022-05-18 15:45:41 +02:00

system-info.txt

[system-info.txt](https://archive.blender.org/developer/F13086972/system-info.txt)

Philipp Oeser commented

2022-05-18 15:48:02 +02:00

Changed status from 'Needs User Info' to: 'Needs Triage'

Raimund Klink commented

2022-05-18 16:28:21 +02:00

@blenderbug12345 Can you please update the driver from the integrated GPU and report back if it helped? If I researched correctly, your driver (4.3.0 - Build 10.18.14.4264) is from 2019

a commented

2022-05-18 16:37:15 +02:00

This comment was removed by @blenderbug12345

*This comment was removed by @blenderbug12345*

a commented

2022-05-18 16:49:09 +02:00

My mistake, you're referring to the Integrated Graphics driver, I'll check to see if that can be upgraded at all...

Upgraded Integrated Graphics driver to 10.18.14.5180 (highest possible available for this hardware)

Retested using the approach detailed above, and the problem is still present.

I notice that after blender is started up:

the first time I try to render the object the render takes > 1 minute
if I change no other settings, but then try rendering again then the render takes approx 1 second, but perhaps it is reading a previous render from a cache?

I notice that in the 3d viewer, if I switch 'Viewport Shading' from Solid to Rendered then the UI freezes for approx 1 minute before displaying the object using EEVEE shading.

I can then toggle between Solid and Rendered quickly and the UI is responsive.

So maybe this only happens the first time EEVEE is called upon in a session, but subsequent times it is fast.

My mistake, you're referring to the Integrated Graphics driver, I'll check to see if that can be upgraded at all... Upgraded Integrated Graphics driver to 10.18.14.5180 (highest possible available for this hardware) Retested using the approach detailed above, and the problem is still present. I notice that after blender is started up: - the first time I try to render the object the render takes > 1 minute - if I change no other settings, but then try rendering again then the render takes approx 1 second, but perhaps it is reading a previous render from a cache? I notice that in the 3d viewer, if I switch 'Viewport Shading' from Solid to Rendered then the UI freezes for approx 1 minute before displaying the object using EEVEE shading. I can then toggle between Solid and Rendered quickly and the UI is responsive. So maybe this only happens the first time EEVEE is called upon in a session, but subsequent times it is fast.

a commented

2022-05-19 19:50:01 +02:00

Bump!

I traced the problem to slow calls like glUseProgram(...). This tells the Integrated Graphics 'GPU' to set up shaders etc. It takes 20 seconds to do this. Other bottlenecks also appear to be related to the gl* routines when a shader is used for the first time. After gl* has put stuff in the cache then subsequent operations are fast.

I'm not sure if OpenGL (or wherever these gl* library routines come from) was upgraded as part of the recent changes in blender or if there are other dependencies that glUseProgram(...) needs which appear slower now.

The proper fix, of course, is to give up and use the NVIDIA GPU all the time.

So I figure we can park or close this ticket due to hardware/drivers being too old to support the latest build.

Thanks for taking a look.

Bump! I traced the problem to slow calls like glUseProgram(...). This tells the Integrated Graphics 'GPU' to set up shaders etc. It takes 20 seconds to do this. Other bottlenecks also appear to be related to the gl* routines when a shader is used for the first time. After gl* has put stuff in the cache then subsequent operations are fast. I'm not sure if OpenGL (or wherever these gl* library routines come from) was upgraded as part of the recent changes in blender or if there are other dependencies that glUseProgram(...) needs which appear slower now. The proper fix, of course, is to give up and use the NVIDIA GPU all the time. So I figure we can park or close this ticket due to hardware/drivers being too old to support the latest build. Thanks for taking a look.

Germano Cavalcante commented

2022-05-20 15:20:48 +02:00

Changed status from 'Needs Triage' to: 'Needs User Info'

Germano Cavalcante commented

2022-05-20 15:20:48 +02:00

@blenderbug12345 since so far apparently only you have reported the issue, if you can bisect or at least find out which build introduced the issue (at https://builder.blender.org/download/daily/archive/) this might help determine what is triggering this issue in Blender.
Without this there is not much we can do here apart from suggesting checking on a newer drivers on the vendor website (and never rely on windows update to take care of drivers).

While this is a real issue, it is only happening to a few people so far. And to troubleshoot it developers needs to have direct access to hardware. And even then it is not clear whether it's a solvable problem from Blender side.

@blenderbug12345 since so far apparently only you have reported the issue, if you can bisect or at least find out which build introduced the issue (at https://builder.blender.org/download/daily/archive/) this might help determine what is triggering this issue in Blender. Without this there is not much we can do here apart from suggesting checking on a newer drivers on the vendor website (and never rely on windows update to take care of drivers). While this is a real issue, it is only happening to a few people so far. And to troubleshoot it developers needs to have direct access to hardware. And even then it is not clear whether it's a solvable problem from Blender side.

a commented

2022-05-21 20:32:39 +02:00

I've been stepping back in time over various commits looking for the one that blew up.

Starting from the latest sources, which build to 3.3.0-alpha I've been stepping back using git reset:

cd blender
git reset --hard 98ad294d17
make clean
test resulting blender.exe

A lot of these steps hit a broken build, which is understandable because not all checkins are good, and anyway the fix is usually in a newer check-in.

The last working build I get to is the one immediately after the muti-library update:

https://developer.blender.org/rB604c33e694375828b0f322010e8e4ac17b4b02f3

This build results in a SLOW render.

If I try my steps to build anything older than this then I get missing files reported, eg:

D:\blender-git\lib\win64_vc15\alembic\include\Alembic/Util/Foundation.h(45,10): fatal error C1083: Cannot open include
file: 'half.h': No such file or directory (compiling source file D:\blender-git\blender\source\blender\io\alembic\expor
ter\abc_custom_props.cc) [D:\blender-git\build_windows_x64_vc17_Release\source\blender\io\alembic\bf_alembic.vcxproj]

So I've not been able to build anything from sources in git that runs FAST.

Is there a better way for me to step back through commits and build a working exe?

I've been stepping back in time over various commits looking for the one that blew up. Starting from the latest sources, which build to 3.3.0-alpha I've been stepping back using git reset: - cd blender - git reset --hard 98ad294d1719eb9cec01af08a0db16558e9964a5 - make clean - test resulting blender.exe A lot of these steps hit a broken build, which is understandable because not all checkins are good, and anyway the fix is usually in a newer check-in. The last working build I get to is the one immediately after the muti-library update: https://developer.blender.org/rB604c33e694375828b0f322010e8e4ac17b4b02f3 This build results in a SLOW render. If I try my steps to build anything older than this then I get missing files reported, eg: ``` D:\blender-git\lib\win64_vc15\alembic\include\Alembic/Util/Foundation.h(45,10): fatal error C1083: Cannot open include file: 'half.h': No such file or directory (compiling source file D:\blender-git\blender\source\blender\io\alembic\expor ter\abc_custom_props.cc) [D:\blender-git\build_windows_x64_vc17_Release\source\blender\io\alembic\bf_alembic.vcxproj] ``` So I've not been able to build anything from sources in git that runs FAST. Is there a better way for me to step back through commits and build a working exe?

Germano Cavalcante commented

2022-05-21 21:04:09 +02:00

Oops, I ended up forgetting the April 29th info.
Reviewing the commits, it's not obvious what causes the slowdown :
Could it be that updating the libraries was the cause?

In #98190#1362271, @blenderbug12345 wrote:
(...)
A lot of these steps hit a broken build, which is understandable because not all checkins are good, and anyway the fix is usually in a newer check-in.

Library changes need to be manually rolled back in SVN for the compilation to work.

I cannot identify what may have caused the glUseProgram to be slow. Could it be the OpenColorIO update?

We could check this by trying a build disabling the WITH_OPENCOLORIO Cmake option. And then check if that results in any change in render time.

Oops, I ended up forgetting the April 29th info. Reviewing the commits, it's not obvious what causes the slowdown :\ Could it be that updating the libraries was the cause? --- > In #98190#1362271, @blenderbug12345 wrote: > (...) > A lot of these steps hit a broken build, which is understandable because not all checkins are good, and anyway the fix is usually in a newer check-in. Library changes need to be manually rolled back in SVN for the compilation to work. --- I cannot identify what may have caused the `glUseProgram` to be slow. Could it be the `OpenColorIO` update? We could check this by trying a build disabling the `WITH_OPENCOLORIO` Cmake option. And then check if that results in any change in render time.

a commented

2022-05-21 22:18:22 +02:00

I hacked CMakeLists.txt on the latest 3.3.0 alpha:

option(WITH_OPENCOLORIO   "Enable OpenColorIO color management" OFF)

and ran make clean, but it's still SLOW. I'm not very familiar with CMake so perhaps that was not the proper way to do it.

I hacked CMakeLists.txt on the latest 3.3.0 alpha: ``` option(WITH_OPENCOLORIO "Enable OpenColorIO color management" OFF) ``` and ran make clean, but it's still SLOW. I'm not very familiar with CMake so perhaps that was not the proper way to do it.

a commented

2022-05-22 11:26:05 +02:00

I did this:

cd ../lib
svn up -r r62864
    this rewinds the recent update to many libraries
cd ../blender
git reset --hard 80859a6cb2726a39fb22cb49f06e0355dc9390a7
    also had to apply the \r whitespace fix to gpu_shader_dependency.cc to stop a crash on startup
    so this is technically: git reset --hard 48d2f536e182468c26a81ec2c2af2638e6768bb0
make clean

The resulting build is SLOW ( > 1 minute )

The preceeding build is FAST, ie:

apr.14 https://developer.blender.org/rB48d2f536e182468c26a81ec2c2af2638e6768bb0 SLOW
...
apr.14 https://developer.blender.org/rB66dc4d4efb88ecf2d18bfa08ab9c43b024ebd2fb FAST

So it looks like the problems appeared in:

GPU: Make nodetree GLSL Codegen render engine agnostic
https://developer.blender.org/rB80859a6cb2726a39fb22cb49f06e0355dc9390a7

note: at some point the builds I was getting were complaining about webp.h not being found, so I commented out the references in blender\imbuf\intern\webp.c just to get past what I think is an unrelated issue.

I did this: ``` cd ../lib svn up -r r62864 this rewinds the recent update to many libraries cd ../blender git reset --hard 80859a6cb2726a39fb22cb49f06e0355dc9390a7 also had to apply the \r whitespace fix to gpu_shader_dependency.cc to stop a crash on startup so this is technically: git reset --hard 48d2f536e182468c26a81ec2c2af2638e6768bb0 make clean ``` The resulting build is SLOW ( > 1 minute ) The preceeding build is FAST, ie: apr.14 https://developer.blender.org/rB48d2f536e182468c26a81ec2c2af2638e6768bb0 SLOW ... apr.14 https://developer.blender.org/rB66dc4d4efb88ecf2d18bfa08ab9c43b024ebd2fb FAST So it looks like the problems appeared in: GPU: Make nodetree GLSL Codegen render engine agnostic https://developer.blender.org/rB80859a6cb2726a39fb22cb49f06e0355dc9390a7 note: at some point the builds I was getting were complaining about webp.h not being found, so I commented out the references in blender\imbuf\intern\webp.c just to get past what I think is an unrelated issue.

Philipp Oeser commented

2022-05-22 11:34:23 +02:00

Changed status from 'Needs User Info' to: 'Needs Triage'

Germano Cavalcante commented

2022-05-23 01:27:48 +02:00

@blenderbug12345, glad you were able to bisect and find the commit that introduced the problem :)

Since glUseProgram is where the code spends the most time, the slowness lies in compiling the shaders.
80859a6cb2 changed the shaders code, but I don't see how it can make the compilation so much slower.

I suspect the problem is related to a feature of some GPU's drivers (like Intel) which is to Cache Shaders.
If some shader code has already been compiled before, if the same code is to be recompiled, the cached shader will be used to avoid this re-compiling.

@blenderbug12345, would you be able to check if this is the case?
The shader cache is located in some Intel folder. You can test by deleting this folder and disabling (somehow) Intel's cache shaders feature.
(unfortunately I don't know how to be of more help. I don't have an Intel or Windows8 available)

@blenderbug12345, glad you were able to bisect and find the commit that introduced the problem :) Since `glUseProgram` is where the code spends the most time, the slowness lies in compiling the shaders. 80859a6cb2 changed the shaders code, but I don't see how it can make the compilation so much slower. I suspect the problem is related to a feature of some GPU's drivers (like Intel) which is to Cache Shaders. If some shader code has already been compiled before, if the same code is to be recompiled, the cached shader will be used to avoid this re-compiling. @blenderbug12345, would you be able to check if this is the case? The shader cache is located in some Intel folder. You can test by deleting this folder and disabling (somehow) Intel's cache shaders feature. (unfortunately I don't know how to be of more help. I don't have an Intel or Windows8 available)

a commented

2022-05-24 01:16:01 +02:00

I'm still looking at this, but I have an early observation.

I'm looking at the behaviour of the 3.3.0-alpha latest build.

glUseProgram takes a compiled/linked binary and puts it on the GPU, and this operation is very slow for ONE of the many shaders that blender asks it to handle.

After a shader is compiled/linked you can find out how big it is, and I looked at all the calls that blender makes when doing an F12 single frame render of the default scene.

I added this code to gl_shaders.cc:

...
glLinkProgram(shader_program_);
GLint binarySize = 0;
glGetProgramiv(shader_program_, GL_PROGRAM_BINARY_LENGTH, &binarySize);
fprintf(stderr, "GLShader: shader = %lu, size = %lu.\n", shader_program_, binarySize);fflush(stderr);
...

There are about 280 unique shaders created for various tasks, and they're called hundreds of times for a simple render like this. Most of the shaders compile/link to a size of around 50000 bytes, some are smaller, some are a bit larger.

One shader compile/links to a size of 1153752 bytes, which is VERY much more than the rest. This is the shader that takes > 20 seconds to return in 3.3.0-alpha.

I compared this with the same numbers you get from 3.2.0-alpha (see the comments above for how I set that up).

The shaders on 3.2.0-alpha compile/link to roughly the same size as before, and there is also one shader that is much larger than the others. However this big shader is 'only' 537031 bytes big, that's 1/2 the size of what appears to be the 'same' shader on 3.3.0-alpha.

note: Shaders have a unique ID for the life time of a blender session and they seem to be created and used in the same order in both 3.2.0 and 3.3.0. Both of the very big shaders have ID 274 when running on my hardware. So I'm pretty sure they're performing the same general function. The code generated on 3.3.0 is just a lot larger.

The slow down in glUseShader might be because of the compiled/linked code size, or perhaps the 3.3.0 shader is just designed to perform a lot more work.

note: I did not find any useful cache controls for the Integrated Graphics processor on my hardware.

I'm still looking at this, but I have an early observation. I'm looking at the behaviour of the 3.3.0-alpha latest build. glUseProgram takes a compiled/linked binary and puts it on the GPU, and this operation is very slow for ONE of the many shaders that blender asks it to handle. After a shader is compiled/linked you can find out how big it is, and I looked at all the calls that blender makes when doing an F12 single frame render of the default scene. I added this code to gl_shaders.cc: ``` ... glLinkProgram(shader_program_); GLint binarySize = 0; glGetProgramiv(shader_program_, GL_PROGRAM_BINARY_LENGTH, &binarySize); fprintf(stderr, "GLShader: shader = %lu, size = %lu.\n", shader_program_, binarySize);fflush(stderr); ... ``` There are about 280 unique shaders created for various tasks, and they're called hundreds of times for a simple render like this. Most of the shaders compile/link to a size of around 50000 bytes, some are smaller, some are a bit larger. One shader compile/links to a size of **1153752** bytes, which is VERY much more than the rest. This is the shader that takes > 20 seconds to return in 3.3.0-alpha. I compared this with the same numbers you get from 3.2.0-alpha (see the comments above for how I set that up). The shaders on 3.2.0-alpha compile/link to roughly the same size as before, and there is also one shader that is much larger than the others. However this big shader is 'only' **537031** bytes big, that's 1/2 the size of what appears to be the 'same' shader on 3.3.0-alpha. note: Shaders have a unique ID for the life time of a blender session and they seem to be created and used in the same order in both 3.2.0 and 3.3.0. Both of the very big shaders have ID 274 when running on my hardware. So I'm pretty sure they're performing the same general function. The code generated on 3.3.0 is just a lot larger. The slow down in glUseShader might be because of the compiled/linked code size, or perhaps the 3.3.0 shader is just designed to perform a lot more work. note: I did not find any useful cache controls for the Integrated Graphics processor on my hardware.

Germano Cavalcante commented

2022-05-24 17:51:06 +02:00

OpenGL commands are asynchronous and many are lazily initialized in the driver.
So, depending on the driver, it is quite possible that a shader is only compiled when glUseProgram is called.
I'm not sure size really impacts performance that much.

But if the size of a supposed same shader changed from 537.031 to 1.153.752, this is interesting information that deserves investigation.

OpenGL commands are asynchronous and many are lazily initialized in the driver. So, depending on the driver, it is quite possible that a shader is only compiled when `glUseProgram` is called. I'm not sure size really impacts performance that much. But if the size of a supposed same shader changed from 537.031 to 1.153.752, this is interesting information that deserves investigation.

a commented

2022-05-25 22:59:40 +02:00

Firstly, I'm not an expert and c++ makes my head hurt, so I might be wrong about this, so...

I've been looking at the sources for the individual shaders that are appended to each program. I added this code around the glCompileShader call and logged the source code that each shader uses.

From gl_shader.cc::create_shader_stage...

 glShaderSource(shader, sources.size(), sources.data(), nullptr);
  fprintf(stderr, "glCompileShader %lu num_sources=%lu\n", shader, sources.size());fflush(stderr);
  int i;
  int size = 0;
  for ( i = 0; i < sources.size(); i++ ) {
	  size += strlen( sources[i] );
  }
  fprintf(stderr, "numChars %lu = %d\n", shader, size);fflush(stderr);
  fprintf(stderr, "--- BEGIN SHADER %lu\n", shader);fflush(stderr);
  for ( i = 0; i < sources.size(); i++ ) {
  	  fprintf(stderr, "\n/* SOURCE %lu %d */\n", shader, i);fflush(stderr);
	  fprintf(stderr, "%s\n", sources[i]);
  }
  fprintf(stderr, "--- END SHADER %lu\n", shader);fflush(stderr);

Typically, a single program might have 2 shaders, each with their own code and each containing a 'void main()...' definition. In some shaders I'm seeing the same code fragments included more than once.

For example, this fragment from common_view_lib.glsl appears twice in the source code for one of the 2 BIG shaders discussed earlier:

float get_depth_from_view_z(float z)
{
  if (ProjectionMatrix[3][3] == 0.0) {
    float d = (-ProjectionMatrix[3][2] / z) - ProjectionMatrix[2][2];
    return d * 0.5 + 0.5;
  }
  else {
    return (z - ViewVecs[0].z) / ViewVecs[1].z;
  }
}

A shader's source code is an array of strings which is gradually appended to as the shader is built. These source strings can be single lines, or multiple-line chunks of code, but they all end up together when the shader's source code is finally set.

There's code in gpu_shader_dependency.cc which ensures that the .glsl code included from a 'pragma BLENDER_REQUIRE(...)' only appears once in each GPUSource object. But I'm not sure if this takes account of other strings which are eventually combined to form the shader's source. So the same BLENDER_REQUIRE(...) might appear in two separate multiline-chunks which then go on to be combined in the finished shader.

I don't know how well the glCompileShader 'compiler' deals with this but I know that these large shaders take a long time to pass glUseProgram the first time they're called.

I also don't know if the shader really does need duplicate code in order to function.

Firstly, I'm not an expert and c++ makes my head hurt, so I might be wrong about this, so... I've been looking at the sources for the individual shaders that are appended to each program. I added this code around the glCompileShader call and logged the source code that each shader uses. From gl_shader.cc::create_shader_stage... ``` glShaderSource(shader, sources.size(), sources.data(), nullptr); fprintf(stderr, "glCompileShader %lu num_sources=%lu\n", shader, sources.size());fflush(stderr); int i; int size = 0; for ( i = 0; i < sources.size(); i++ ) { size += strlen( sources[i] ); } fprintf(stderr, "numChars %lu = %d\n", shader, size);fflush(stderr); fprintf(stderr, "--- BEGIN SHADER %lu\n", shader);fflush(stderr); for ( i = 0; i < sources.size(); i++ ) { fprintf(stderr, "\n/* SOURCE %lu %d */\n", shader, i);fflush(stderr); fprintf(stderr, "%s\n", sources[i]); } fprintf(stderr, "--- END SHADER %lu\n", shader);fflush(stderr); ``` Typically, a single program might have 2 shaders, each with their own code and each containing a 'void main()...' definition. In some shaders I'm seeing the same code fragments included more than once. For example, this fragment from common_view_lib.glsl appears twice in the source code for one of the 2 BIG shaders discussed earlier: ``` float get_depth_from_view_z(float z) { if (ProjectionMatrix[3][3] == 0.0) { float d = (-ProjectionMatrix[3][2] / z) - ProjectionMatrix[2][2]; return d * 0.5 + 0.5; } else { return (z - ViewVecs[0].z) / ViewVecs[1].z; } } ``` A shader's source code is an array of strings which is gradually appended to as the shader is built. These source strings can be single lines, or multiple-line chunks of code, but they all end up together when the shader's source code is finally set. There's code in gpu_shader_dependency.cc which ensures that the .glsl code included from a 'pragma BLENDER_REQUIRE(...)' only appears once in each GPUSource object. But I'm not sure if this takes account of other strings which are eventually combined to form the shader's source. So the same BLENDER_REQUIRE(...) might appear in two separate multiline-chunks which then go on to be combined in the finished shader. I don't know how well the glCompileShader 'compiler' deals with this but I know that these large shaders take a long time to pass glUseProgram the first time they're called. I also don't know if the shader really does need duplicate code in order to function.

Germano Cavalcante commented

2022-05-26 21:50:20 +02:00

Even if the source gets bigger, I don't think the difference is that big to justify the reported slowness. I still think Intel's shader cache system must be related.

a commented

2022-05-26 23:52:12 +02:00

Well I had a closer look and the duplicate code fragments are a known issue. I didn't notice that they're inside an ifndef. I'll keep looking into this but I'll wait a while longer next time before jumping to wrong conclusions.

Richard Antalik commented

2022-06-08 16:09:26 +02:00

Added subscriber: @iss

Richard Antalik commented

2022-06-08 16:09:26 +02:00

Changed status from 'Needs Triage' to: 'Needs User Info'

Richard Antalik commented

2022-06-08 16:09:26 +02:00

@blenderbug12345 do you still have this issue?

Just a question - I have checked out YT video provided and to me it seems, that this is only issue when you render for first time? Can you check that?
If sequencer is enabled in post processing, but there is no strip, it does not execute any VSE rendering code, so first and third render in that video had equivalent settings from what I can tell and first was slow, then third was fast, so that's why I ask.

@blenderbug12345 do you still have this issue? Just a question - I have checked out YT video provided and to me it seems, that this is only issue when you render for first time? Can you check that? If sequencer is enabled in post processing, but there is no strip, it does not execute any VSE rendering code, so first and third render in that video had equivalent settings from what I can tell and first was slow, then third was fast, so that's why I ask.

a commented

2022-06-09 11:40:21 +02:00

Hi @iss,

yes the problem still happens.

I think the video is too complicated. The problem has nothing to do with the VSE. The FIRST render of a 3D image is slow when rendering the default cube from the 3D Viewport. When you render the cube a second time then it is fast.

So once the shader has been compiled and cached then the render is fast. But compiling the shader and using it the first time is slow.

Hi @iss, yes the problem still happens. I think the video is too complicated. The problem has nothing to do with the VSE. The FIRST render of a 3D image is slow when rendering the default cube from the 3D Viewport. When you render the cube a second time then it is fast. So once the shader has been compiled and cached then the render is fast. But compiling the shader and using it the first time is slow.

Richard Antalik commented

2022-06-09 16:29:30 +02:00

Thanks for clarification, that's what I thought is the case. So your problem is, that compiled shader does not persist in cache, is that correct?

To me this seems like issue within driver and its infrastructure, unless Blender (or driver...) adds some randomness to shader on purpose really. But since you was able to identify commit that caused this behavior is strange too... Have you tried to modify the shader code itself to see whether this would resolve the delay? Perhaps make it grayscale by overwriting green and blue channels with red one.

Thanks for clarification, that's what I thought is the case. So your problem is, that compiled shader does not persist in cache, is that correct? To me this seems like issue within driver and its infrastructure, unless Blender (or driver...) adds some randomness to shader on purpose really. But since you was able to identify commit that caused this behavior is strange too... Have you tried to modify the shader code itself to see whether this would resolve the delay? Perhaps make it grayscale by overwriting green and blue channels with red one.

Richard Antalik changed title from ~~Render of 3D image is very slow when an EMPTY VSE is in the Post Processing pipeline.~~ to Render of 3D image is very slow when

2022-06-09 18:19:28 +02:00

Richard Antalik changed title from ~~Render of 3D image is very slow when~~ to Render of 3D image is very slow

2022-06-09 18:23:13 +02:00

a commented

2022-06-11 00:11:59 +02:00

Hi @iss

I managed to make the rendering faster on my hardware/driver by modifying one of the shaders.

I've modified my 3.3.0-alpha to print out the source code for each shader it passes to useProgram, and I've saved the results to a separate file. So shader number 276 (on my machine) is the slow one and I've written the source to ./Shaders/276.txt.

I copied this 276.txt to my276.txt and hacked that code. I removed function definitions that were never called thinking that perhaps the shader binary was just too big to work well on my hardware. I removed quite a lot of unused code but still have around 5600 lines of .glsl in my276.txt.

When I run blender and render the default cube, I'm able detect when shader 276 is about to be built and then throw away the original shader source. I then copy the text from my276.txt instead. Blender is happy to do this and the result runs just as slow as the original, and the resulting image looks good.

I went back to my276.txt and tried knocking out various function calls to see if any of these contributed to the slowness. For example, I would use 'return' on the first line of a function, so that it still got called but had no effect on the rendered image.

After a lot of experimentation I got down to the code defined for the function node_bsdf_principled(...). This comes from gpu_shader_material_principled.glsl and is combined with other fragments to form shader 276. In that function there's this if/else/ statement:

if (do_diffuse == 0.0 && do_refraction == 0.0 && do_clearcoat != 0.0) {
    /* Metallic & Clearcoat case. */
    result = closure_eval(reflection_data, clearcoat_data);
  }
  else if (do_diffuse == 0.0 && do_refraction == 0.0 && do_clearcoat == 0.0) {
    /* Metallic case. */
    result = closure_eval(reflection_data);
  }
  else if (do_diffuse != 0.0 && do_refraction == 0.0 && do_clearcoat == 0.0) {
    /* Dielectric case. */
    result = closure_eval(diffuse_data, reflection_data);
  }
  else if (do_diffuse == 0.0 && do_refraction != 0.0 && do_clearcoat == 0.0) {
    /* Glass case. */
    result = closure_eval(reflection_data, refraction_data);
  }
  else {
    /* Un-optimized case. */
    result = closure_eval(diffuse_data, reflection_data, clearcoat_data, refraction_data);
  }

After some tweaking I ended up wrapping the whole thing in ' if (false) ', and just called the un-optimized case directly:

if ( false ) {

    // above code

}

result = closure_eval(diffuse_data, reflection_data, clearcoat_data, refraction_data);

And my276.txt renders the cube in < 10 seconds the first time it is called, compared to 1m20s in the original 276.txt

So I think the un-optimized case is best for my hardware/driver and something in one of the optimized cases is causing the slowdown.

Hi @iss I managed to make the rendering faster on my hardware/driver by modifying one of the shaders. I've modified my 3.3.0-alpha to print out the source code for each shader it passes to useProgram, and I've saved the results to a separate file. So shader number 276 (on my machine) is the slow one and I've written the source to ./Shaders/276.txt. I copied this 276.txt to my276.txt and hacked that code. I removed function definitions that were never called thinking that perhaps the shader binary was just too big to work well on my hardware. I removed quite a lot of unused code but still have around 5600 lines of .glsl in my276.txt. When I run blender and render the default cube, I'm able detect when shader 276 is about to be built and then throw away the original shader source. I then copy the text from my276.txt instead. Blender is happy to do this and the result runs just as slow as the original, and the resulting image looks good. I went back to my276.txt and tried knocking out various function calls to see if any of these contributed to the slowness. For example, I would use 'return' on the first line of a function, so that it still got called but had no effect on the rendered image. After a lot of experimentation I got down to the code defined for the function node_bsdf_principled(...). This comes from gpu_shader_material_principled.glsl and is combined with other fragments to form shader 276. In that function there's this if/else/ statement: ``` if (do_diffuse == 0.0 && do_refraction == 0.0 && do_clearcoat != 0.0) { /* Metallic & Clearcoat case. */ result = closure_eval(reflection_data, clearcoat_data); } else if (do_diffuse == 0.0 && do_refraction == 0.0 && do_clearcoat == 0.0) { /* Metallic case. */ result = closure_eval(reflection_data); } else if (do_diffuse != 0.0 && do_refraction == 0.0 && do_clearcoat == 0.0) { /* Dielectric case. */ result = closure_eval(diffuse_data, reflection_data); } else if (do_diffuse == 0.0 && do_refraction != 0.0 && do_clearcoat == 0.0) { /* Glass case. */ result = closure_eval(reflection_data, refraction_data); } else { /* Un-optimized case. */ result = closure_eval(diffuse_data, reflection_data, clearcoat_data, refraction_data); } ``` After some tweaking I ended up wrapping the whole thing in ' if (false) ', and just called the un-optimized case directly: ``` if ( false ) { // above code } result = closure_eval(diffuse_data, reflection_data, clearcoat_data, refraction_data); ``` And my276.txt renders the cube in < 10 seconds the first time it is called, compared to 1m20s in the original 276.txt So I think the un-optimized case is best for my hardware/driver and something in one of the optimized cases is causing the slowdown.

Richard Antalik commented

2022-06-13 17:39:37 +02:00

Added subscribers: @Gioxyer, @OmarEmaraDev

Richard Antalik commented

2022-06-13 17:40:03 +02:00

Changed status from 'Needs User Info' to: 'Needs Triage'

Richard Antalik commented

2022-06-13 17:40:03 +02:00

Added subscribers: @fclem, @Jeroen-Bakker

Richard Antalik commented

2022-06-13 17:40:03 +02:00

Interesting, my thinking was, that modification of shader may change its hash, so if this is problem with driver cache it could somehow do something different... But I have found another report with same issue, so it's not limited to your system.

@fclem, @Jeroen-Bakker does above comment ring a bell?

Interesting, my thinking was, that modification of shader may change its hash, so if this is problem with driver cache it could somehow do something different... But I have found another report with same issue, so it's not limited to your system. @fclem, @Jeroen-Bakker does above comment ring a bell?

a commented

2022-06-14 16:27:15 +02:00

I had another look at the big if/else statment. I know that when rendering the default cube, only this branch is called:

  else if (do_diffuse != 0.0 && do_refraction == 0.0 && do_clearcoat == 0.0) {
    /* Dielectric case. */
    result = closure_eval(diffuse_data, reflection_data);
  }

If I comment out the other ' result = closure_eval(... ' calls in the if/else then the first render is much faster.

I suspect that then you comment out a function call, then the compiler (either gsgl or driver bytecode) decides not to compile the function code at all. This could explain why the ' if ( false ) ' worked so quickly. None of the other closure_eval variants was being compiled.

So perhaps I just have a slow compiler.

I don't have much visibility on what the compiler/driver are doing with the source code, so I don't know if the closure_eval variants could be written in a different way to allow the compiler to process them faster.

I had another look at the big if/else statment. I know that when rendering the default cube, only this branch is called: ``` else if (do_diffuse != 0.0 && do_refraction == 0.0 && do_clearcoat == 0.0) { /* Dielectric case. */ result = closure_eval(diffuse_data, reflection_data); } ``` If I comment out the other ' result = closure_eval(... ' calls in the if/else then the first render is much faster. I suspect that then you comment out a function call, then the compiler (either gsgl or driver bytecode) decides not to compile the function code at all. This could explain why the ' if ( false ) ' worked so quickly. None of the other closure_eval variants was being compiled. So perhaps I just have a slow compiler. I don't have much visibility on what the compiler/driver are doing with the source code, so I don't know if the closure_eval variants could be written in a different way to allow the compiler to process them faster.

Clément Foucault commented

2022-06-19 16:35:02 +02:00

Yeah this is the compiler not wanting to cooperate even if all the configuration variables are set as const.

Not sure we can do much about that instead of trying to workaround this by other means which would make our shader code generation much more complex.

Yeah this is the compiler not wanting to cooperate even if all the configuration variables are set as `const`. Not sure we can do much about that instead of trying to workaround this by other means which would make our shader code generation much more complex.

a commented

2022-06-20 21:25:46 +02:00

I'm currently just doing this as a hack to: gpu_shader_material_principled.glsl

#ifdef COMPILER_IS_FAST

if ( ... ) {
} elsif ( ... ) {
} elsif ( ... ) {
...
} else {
}

#else

result = closure_eval(diffuse_data, reflection_data, clearcoat_data, refraction_data);

#endif

It would be nice if there was an official way to profile shaders as they're built, and update a list of #defines that the codegen could add to the .glsl headers. That way blender could learn that it's running on rubbish hardware and maybe recompile the slow-compiling shaders so that the new #defines cause different code to be picked up.

I'm assuming that some shaders will be recompiled eventually over the course of a session, but I could be wrong about that.

Or maybe provide a way for regular users to add a #define that is then added to every shader before it's compiled.

I'm currently just doing this as a hack to: gpu_shader_material_principled.glsl ``` #ifdef COMPILER_IS_FAST if ( ... ) { } elsif ( ... ) { } elsif ( ... ) { ... } else { } #else result = closure_eval(diffuse_data, reflection_data, clearcoat_data, refraction_data); #endif ``` It would be nice if there was an official way to profile shaders as they're built, and update a list of #defines that the codegen could add to the .glsl headers. That way blender could learn that it's running on rubbish hardware and maybe recompile the slow-compiling shaders so that the new #defines cause different code to be picked up. I'm assuming that some shaders will be recompiled eventually over the course of a session, but I could be wrong about that. Or maybe provide a way for regular users to add a #define that is then added to every shader before it's compiled.

Rodrigo commented

2022-07-05 22:22:41 +02:00

Added subscriber: @Rodrigo_S.T

Boyd Mouritsen commented

2022-07-08 10:15:28 +02:00

Added subscriber: @boydmouritsen

Boyd Mouritsen commented

2022-07-08 10:15:28 +02:00

While I understand that workarounds would make the shader code generation more complex, the alternative (at least for me) is being stuck at version 3.1.x. This bug makes blender 3.2.x+ unviable for me and likely others.
I guess it comes down to whether Blender decides to leave these users behind and avoid complexity, or if the complexity is worth it to keep the users?
I dunno the answer but if Blender leaves this as is, perhaps consider announcing new minimum specs for 3.2.x+ releases to avoid any frustration.

While I understand that workarounds would make the shader code generation more complex, the alternative (at least for me) is being stuck at version 3.1.x. This bug makes blender 3.2.x+ unviable for me and likely others. I guess it comes down to whether Blender decides to leave these users behind and avoid complexity, or if the complexity is worth it to keep the users? I dunno the answer but if Blender leaves this as is, perhaps consider announcing new minimum specs for 3.2.x+ releases to avoid any frustration.

Boyd Mouritsen commented

2022-07-12 16:06:34 +02:00

In #98190#1376514, @fclem wrote:
Yeah this is the compiler not wanting to cooperate even if all the configuration variables are set as const.

Not sure we can do much about that instead of trying to workaround this by other means which would make our shader code generation much more complex.

This is likely due to the constants here being used in a series of comparisons (&&) to get the result of what should be it's own constant. A trivial quirk, but the compiler assumes the outcomes of these comparisons aren't necessarily constant, so it takes all branches.

> In #98190#1376514, @fclem wrote: > Yeah this is the compiler not wanting to cooperate even if all the configuration variables are set as `const`. > > Not sure we can do much about that instead of trying to workaround this by other means which would make our shader code generation much more complex. This is likely due to the constants here being used in a series of comparisons (&&) to get the result of what should be it's own constant. A trivial quirk, but the compiler assumes the outcomes of these comparisons aren't necessarily constant, so it takes all branches.

blender-admin commented

2022-09-02 13:48:55 +02:00

This issue was referenced by de818d81c3

This issue was referenced by de818d81c3f9868ca78399fa7f106bed893e540f

Clément Foucault commented

2022-09-02 13:57:40 +02:00

Changed status from 'Needs Triage' to: 'Resolved'

Clément Foucault closed this issue

2022-09-02 13:57:40 +02:00

Clément Foucault self-assigned this 2022-09-02 13:57:40 +02:00

Clément Foucault referenced this issue

2023-05-30 17:36:58 +02:00