Opening even remotely complex scenes with many objects takes much longer than before #89194

New Issue

Rainer Trummer · 2021-06-16T11:50:37+02:00

Rainer Trummer commented

2021-06-16 11:50:37 +02:00

System Information
Operating system: Windows-10-10.0.19041-SP0 64 Bits
Graphics card: Quadro RTX 4000/PCIe/SSE2 NVIDIA Corporation 4.5.0 NVIDIA 461.33

Blender Version
Broken: version: 3.0.0 Alpha, branch: master, commit date: 2021-06-15 14:45, commit ID: fcc844f8, BLI: use explicit task isolation, no longer part of parallel operations
Worked: 3.0.0 Alpha, branch: master, commit date: 2021-06-15 14:45, hash: b3f0dc2907

Short description of error
Most of my more complex scenes that opened just fine with the commit ID b3f0dc29, hash: b3f0dc2907 (which is the one right before the broken one) do not ever get displayed, Blender just freezes for an unknown amount of time. This is true for scenes that contain many mesh objects, which are linked into a main file. Small scenes still open just fine.

As far as I can tell, Blender does complete loading of the scene, but then just drops to 0% activity in the Task Manager, and never updates the Viewport. It also does not accept any input, it's just frozen.

When trying to put together a debug file, I noticed that loading times increased a lot between the two mentioned commits (or even 2.93). With the provided demo file I measure roughly a doubling in load times when loading the DemoCrash_Mainfile.blend between 2.93 and current master. Note that this demo file only linkes four simple mesh objects plus 36.000 empties.

Exact steps for others to reproduce the error
Open this file here
File_Open_Regression.zip
and unzip the content. Then open DemoCrash_Mainfile.blend and measure loading times.

On my system:
Blender 2.93: roughly 25 seconds for DemoCrash_Mainfile.blend
Blender master: roughly 50 seconds for DemoCrash_Mainfile.blend

opening DemoCrash.blend, which contains most of the data, takes less than 10 seconds in both cases.

**System Information** Operating system: Windows-10-10.0.19041-SP0 64 Bits Graphics card: Quadro RTX 4000/PCIe/SSE2 NVIDIA Corporation 4.5.0 NVIDIA 461.33 **Blender Version** Broken: version: 3.0.0 Alpha, branch: master, commit date: 2021-06-15 14:45, commit ID: `fcc844f8`, BLI: use explicit task isolation, no longer part of parallel operations Worked: 3.0.0 Alpha, branch: master, commit date: 2021-06-15 14:45, hash: `b3f0dc2907` **Short description of error** Most of my more complex scenes that opened just fine with the commit ID `b3f0dc29`, hash: `b3f0dc2907` (which is the one right before the broken one) do not ever get displayed, Blender just freezes for an unknown amount of time. This is true for scenes that contain many mesh objects, which are linked into a main file. Small scenes still open just fine. As far as I can tell, Blender does complete loading of the scene, but then just drops to 0% activity in the Task Manager, and never updates the Viewport. It also does not accept any input, it's just frozen. When trying to put together a debug file, I noticed that loading times increased a lot between the two mentioned commits (or even 2.93). With the provided demo file I measure roughly a doubling in load times when loading the `DemoCrash_Mainfile.blend` between 2.93 and current master. Note that this demo file only linkes four simple mesh objects plus 36.000 empties. **Exact steps for others to reproduce the error** Open this file here [File_Open_Regression.zip](https://archive.blender.org/developer/F10175161/File_Open_Regression.zip) and unzip the content. Then open `DemoCrash_Mainfile.blend` and measure loading times. On my system: Blender 2.93: roughly 25 seconds for `DemoCrash_Mainfile.blend` Blender master: roughly 50 seconds for `DemoCrash_Mainfile.blend` opening `DemoCrash.blend`, which contains most of the data, takes less than 10 seconds in both cases.

Rainer Trummer commented

2021-06-16 11:50:37 +02:00

Added subscriber: @RainerTrummer

Rainer Trummer changed title from ~~Opening even remotely complex scenes with many objects never completes~~ to Opening even remotely complex scenes with many objects takes much longer than before

2021-06-16 15:32:06 +02:00

Brecht Van Lommel was assigned by Rainer Trummer

2021-06-18 10:08:35 +02:00

Brecht Van Lommel removed their assignment 2021-06-18 21:18:52 +02:00

Brecht Van Lommel commented

2021-06-18 21:18:52 +02:00

Added subscriber: @brecht

Brecht Van Lommel commented

2021-06-18 21:18:52 +02:00

I can see that buildbot builds of 2.93 and master have a performance difference. But I can not confirm with my own build that fcc844f8 is what makes the difference.

Bisecting is not working well here since the load times vary quite a bit even for the same commits, and trying multiple times to build fcc844f8 and b3f0dc29 I did not find a significant difference.

If any other developer can confirm this, it would be good to run a profiler or break in a debugger to see where the extra time is spent.

I can see that buildbot builds of 2.93 and master have a performance difference. But I can not confirm with my own build that fcc844f8 is what makes the difference. Bisecting is not working well here since the load times vary quite a bit even for the same commits, and trying multiple times to build fcc844f8 and b3f0dc29 I did not find a significant difference. If any other developer can confirm this, it would be good to run a profiler or break in a debugger to see where the extra time is spent.

Ray molenkamp commented

2021-06-18 22:21:23 +02:00

Added subscriber: @LazyDodo

Ray molenkamp commented

2021-06-18 22:21:23 +02:00

i didn't have a final 2.93 copy, so used 2.92 to benchmark against

42s to open in 2.92 (official release)
57s to open in 3.0 (todays master)

perf in 2.92 isn't stellar either for such a simple scene..

{F10180653, width=100%}

So of that 57s , 42s is being spend in BLI_FindString and 15 in id_sort_by_name haven't looked why that is, but it feels excessive

i didn't have a final 2.93 copy, so used 2.92 to benchmark against 42s to open in 2.92 (official release) 57s to open in 3.0 (todays master) perf in 2.92 isn't stellar either for such a simple scene.. {[F10180653](https://archive.blender.org/developer/F10180653/image.png), width=100%} So of that 57s , 42s is being spend in `BLI_FindString` and 15 in `id_sort_by_name` haven't looked why that is, but it feels excessive

Hans Goudey commented

2021-06-18 22:42:17 +02:00

Added subscriber: @HooglyBoogly

Hans Goudey commented

2021-06-18 22:42:17 +02:00

I wonder if e4ca6b93ad might be a culprit then

I wonder if e4ca6b93ad might be a culprit then

Rainer Trummer commented

2021-06-19 10:55:35 +02:00

Greatly appreciate everyone investigating this! From my side I can only confirm that reverting the commit I mentioned resolves my problems, but of course the source could be somewhere else entirely. Really difficult to narrow down how to reproduce the problem. For me, production scenes in the company don‘t open within 10 minutes, at that point I kill the Blender process in the task manager. 2.93 opens the same scene in 45 seconds.

Is it possible that this is a Windows platform only issue? I wasn‘t testing under Linux in a while now, so differences here are totally possible.

Greatly appreciate everyone investigating this! From my side I can only confirm that reverting the commit I mentioned resolves my problems, but of course the source could be somewhere else entirely. Really difficult to narrow down how to reproduce the problem. For me, production scenes in the company don‘t open within 10 minutes, at that point I kill the Blender process in the task manager. 2.93 opens the same scene in 45 seconds. Is it possible that this is a Windows platform only issue? I wasn‘t testing under Linux in a while now, so differences here are totally possible.

Brecht Van Lommel commented

2021-06-19 12:48:21 +02:00

In #89194#1179211, @RainerTrummer wrote:
Greatly appreciate everyone investigating this! From my side I can only confirm that reverting the commit I mentioned resolves my problems, but of course the source could be somewhere else entirely. Really difficult to narrow down how to reproduce the problem. For me, production scenes in the company don‘t open within 10 minutes, at that point I kill the Blender process in the task manager. 2.93 opens the same scene in 45 seconds.

It seems like you reported two different bugs then, one about slower loading of files for which you provided a repro case, and one about Blender hanging for which you did not.

> In #89194#1179211, @RainerTrummer wrote: > Greatly appreciate everyone investigating this! From my side I can only confirm that reverting the commit I mentioned resolves my problems, but of course the source could be somewhere else entirely. Really difficult to narrow down how to reproduce the problem. For me, production scenes in the company don‘t open within 10 minutes, at that point I kill the Blender process in the task manager. 2.93 opens the same scene in 45 seconds. It seems like you reported two different bugs then, one about slower loading of files for which you provided a repro case, and one about Blender hanging for which you did not.

Brecht Van Lommel commented

2021-06-19 12:59:11 +02:00

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

Ray molenkamp commented

2021-06-19 18:22:11 +02:00

could be the same bug to, just with larger files, O(n^2) solution to a problem could easily exhibit that behaviour

could be the same bug to, just with larger files, [O(n^2)](https://twitter.com/BruceDawson0xB/status/1120381406700429312) solution to a problem could easily exhibit that behaviour

Brecht Van Lommel commented

2021-06-19 18:49:07 +02:00

The task isolation change is unlikely to introduce O(n^2) behavior, but is likely to introduce a deadlock.

Ray molenkamp commented

2021-06-19 19:00:18 +02:00

there's no threading at play here, only the main thread is active, expand_doit_library is being a tad optimistic by calling is_yet_read which loops though all objects ....... for every object added, and that gets expensive as the number of objects grows.

there's no threading at play here, only the main thread is active, `expand_doit_library` is being a tad optimistic by calling `is_yet_read` which loops though all objects ....... for every object added, and that gets expensive as the number of objects grows.

Brecht Van Lommel commented

2021-06-19 19:15:44 +02:00

Yes, no threading at play for the attached .blend, yet a threading related commit identified as the cause for another production .blend. That supports there being two bugs here.

Rainer Trummer commented

2021-06-20 19:25:20 +02:00

It seems like you reported two different bugs then, one about slower loading of files for which you provided a repro case, and one about Blender hanging for which you did not.

@brecht I initially thought Blender would freeze entirely when trying to open our production scenes in the company. When I later tried to put together a simple scene where developers could reproduce the problem, I could not find a simple case where loading would freeze entirely. However then I noticed the increase in loading times. My thinking then was, that maybe Blender did not really freeze on my production scenes either, it propably just takes an excessively long time to load. I never waited for the process long enough to complete though, after max 10-15 minutes I stopped the attempt. Since the production scenes are for a racing team competing in World Championships, I have no possibilities to share the original affected files.

Hope this clarifies how the bug report was phrased like this?

> It seems like you reported two different bugs then, one about slower loading of files for which you provided a repro case, and one about Blender hanging for which you did not. @brecht I initially thought Blender would freeze entirely when trying to open our production scenes in the company. When I later tried to put together a simple scene where developers could reproduce the problem, I could not find a simple case where loading would freeze entirely. However then I noticed the increase in loading times. My thinking then was, that maybe Blender did not really freeze on my production scenes either, it propably just takes an excessively long time to load. I never waited for the process long enough to complete though, after max 10-15 minutes I stopped the attempt. Since the production scenes are for a racing team competing in World Championships, I have no possibilities to share the original affected files. Hope this clarifies how the bug report was phrased like this?

Brecht Van Lommel commented

2021-06-21 16:18:06 +02:00

Right, I understand how it would look like it's the same issue, but to me it seems likely that's it not.

If you are able to run Blender with the production file in a debugger, it would be interesting to see where it is hanging (after a few minutes). That could give us a good clue for the cause.

Right, I understand how it would look like it's the same issue, but to me it seems likely that's it not. If you are able to run Blender with the production file in a debugger, it would be interesting to see where it is hanging (after a few minutes). That could give us a good clue for the cause.

Brecht Van Lommel commented

2021-06-21 19:31:17 +02:00

I found a repro case for the deadlock. That is hopefully fixed now, but there is still a performance issue. More details in D11603: BLI: use explicit task isolation, no longer part of parallel operations.

I found a repro case for the deadlock. That is hopefully fixed now, but there is still a performance issue. More details in [D11603: BLI: use explicit task isolation, no longer part of parallel operations](https://archive.blender.org/developer/D11603).

Rainer Trummer commented

2021-06-22 09:28:56 +02:00

Hi @brecht your fix indeed resolved the scene opening problems for me!

I've benchmarked opening times now on different scenarios on my system, always freshly restarting Blender and then trying to open the scene (cycle repeated at least once). Here are the results (all measured on Windows 10, all files reside on a network drive and link other data in):

production scene that initially refused to open:
current master: ~45-50 seconds
2.93 release: ~47-48 seconds

another less complex production scene, which before also refused to open:
current master: ~17-22 seconds
2.93 release: ~16-18 seconds

provided debug file, read from a local ssd drive:
current master: ~33-38 seconds
2.93 release: ~26-28 seconds

conclusion: 2.93 release tends to be a little faster indeed. Interestingly, it also shows a smaller variance in loading times when you repeat the cycle. The time increase does not look exponential at first glance.
However, for me the main problem of this bug report is fixed, the increase in loading times isn't at a critical level. I leave it up to you if you want to close the report or continue searching for performance improvements.

Hi @brecht your fix indeed resolved the scene opening problems for me! I've benchmarked opening times now on different scenarios on my system, always freshly restarting Blender and then trying to open the scene (cycle repeated at least once). Here are the results (all measured on Windows 10, all files reside on a network drive and link other data in): **production scene that initially refused to open:** current master: ~45-50 seconds 2.93 release: ~47-48 seconds **another less complex production scene, which before also refused to open:** current master: ~17-22 seconds 2.93 release: ~16-18 seconds **provided debug file, read from a local ssd drive:** current master: ~33-38 seconds 2.93 release: ~26-28 seconds conclusion: 2.93 release tends to be a little faster indeed. Interestingly, it also shows a smaller variance in loading times when you repeat the cycle. The time increase does not look exponential at first glance. However, for me the main problem of this bug report is fixed, the increase in loading times isn't at a critical level. I leave it up to you if you want to close the report or continue searching for performance improvements.

Brecht Van Lommel commented

2021-06-22 19:30:20 +02:00

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

Brecht Van Lommel commented

2021-06-22 19:30:20 +02:00

Added subscriber: @mont29

Brecht Van Lommel commented

2021-06-22 19:30:20 +02:00

It's up to @mont29 if he wants to consider this a bug and investigate performance regressions in .blend file loading, or not.

Bastien Montagne commented

2021-06-28 15:00:05 +02:00

Sorting libdata is indeed going to increase a bit loading time, not sure how much it accounts here...

More interested in the graph from @LazyDodo here, string lookup is indeed always very expensive, that's why we use hashes most of the time, guess that's another case to try it on. Will switch the task as TODO and check on this later.

Sorting libdata is indeed going to increase a bit loading time, not sure how much it accounts here... More interested in the graph from @LazyDodo here, string lookup is indeed always very expensive, that's why we use hashes most of the time, guess that's another case to try it on. Will switch the task as TODO and check on this later.

Ray molenkamp commented

2021-06-28 18:11:49 +02:00

Given it is a sorted list, i took a quick stab (temp hack in P2221) at implementing a binary search for is_yet_read which did speed it up a little (took ~ 5 sec off) but it moved to hot spot to BLI_listbase_count which should be trivial as well to figure out , but some lib work came along and i had to shelf this, feel free to run with it.

Heads up: while the binary search seems to work, I have not proven its correctness yet, so be weary if you re-use that code

Given it is a sorted list, i took a quick stab (temp hack in [P2221](https://archive.blender.org/developer/P2221.txt)) at implementing a binary search for `is_yet_read ` which did speed it up a little (took ~ 5 sec off) but it moved to hot spot to `BLI_listbase_count` which should be trivial as well to figure out , but some lib work came along and i had to shelf this, feel free to run with it. Heads up: while the binary search seems to work, I have not proven its correctness yet, so be weary if you re-use that code

Philipp Oeser commented

2021-07-01 14:33:14 +02:00

Added subscriber: @lichtwerk