Slow Cycles CLI render with proper tile sizes #76767

New Issue

Lord Odin · 2020-05-14T21:27:37+02:00

Lord Odin commented

2020-05-14 21:27:37 +02:00

System Information
Operating system: Windows-10-10.0.18362-SP0 64 Bits
Graphics card: GeForce RTX 2080/PCIe/SSE2 NVIDIA Corporation 4.5.0 NVIDIA 445.75

Blender Version
Broken: version: 2.90 (sub 0), branch: master, commit date: 2020-04-20 02:15, hash: 2a96e8be39

Short description of error
Rendering any file with smaller tile sizes in CLI is much slower than rendering inside of the GUI

Even on a 32 thread CPU 128x128 is faster than 16x16 by a long shot, even when there is less tiles than cpu threads

Exact steps for others to reproduce the error
CLI Render any Blend file with different tile sizes on CPU

ImywnvmB0k.mp4

**System Information** Operating system: Windows-10-10.0.18362-SP0 64 Bits Graphics card: GeForce RTX 2080/PCIe/SSE2 NVIDIA Corporation 4.5.0 NVIDIA 445.75 **Blender Version** Broken: version: 2.90 (sub 0), branch: master, commit date: 2020-04-20 02:15, hash: `2a96e8be39` **Short description of error** Rendering any file with smaller tile sizes in CLI is much slower than rendering inside of the GUI Even on a 32 thread CPU 128x128 is faster than 16x16 by a long shot, even when there is less tiles than cpu threads **Exact steps for others to reproduce the error** CLI Render any Blend file with different tile sizes on CPU [ImywnvmB0k.mp4](https://archive.blender.org/developer/F8536009/ImywnvmB0k.mp4)

Lord Odin commented

2020-05-14 21:27:37 +02:00

Added subscriber: @derekbarker

Ray molenkamp commented

2020-05-14 21:43:29 +02:00

Added subscriber: @LazyDodo

Ray molenkamp commented

2020-05-14 21:43:29 +02:00

the scrolling of the console takes a significant amount of time, redirect it to a file and you should do much better

console   59.32
to file   29.92
GUI       25.04

The time difference left between the two, can probably be explained by the fact the GUI version can apply the color transform on the GPU while the console one has to do it on the CPU (but i admit, i'm guessing here, well guessing at that's where the difference comes from, i'm sure about the color transform being gpu for GUI, cpu for CLI)

the scrolling of the console takes a significant amount of time, redirect it to a file and you should do much better ``` console 59.32 to file 29.92 GUI 25.04 ``` The time difference left between the two, can probably be explained by the fact the GUI version can apply the color transform on the GPU while the console one has to do it on the CPU (but i admit, i'm guessing here, well guessing at that's where the difference comes from, i'm sure about the color transform being gpu for GUI, cpu for CLI)

Lord Odin commented

2020-05-15 17:45:56 +02:00

It seems writing to a file or just throwing it in to nothingness does help a bit but I've been running CLI for a long time never really noticed a slowdown like this, Though lately I am trying to achieve sub 500ms renders for web related stuff which I can actually do in cycles without denoising.

I know printing to CLI is slow but usually powershell has much less effect on programs printing a lot compared to the CMD. CMD is much slower than powershell and cygwin termnial

It seems writing to a file or just throwing it in to nothingness does help a bit but I've been running CLI for a long time never really noticed a slowdown like this, Though lately I am trying to achieve sub 500ms renders for web related stuff which I can actually do in cycles without denoising. I know printing to CLI is slow but usually powershell has much less effect on programs printing a lot compared to the CMD. CMD is much slower than powershell and cygwin termnial

Ray molenkamp commented

2020-05-15 17:56:11 +02:00

I ran it though the profiler yesterday to see what was up, all threads were fighting over a mutex inside conhost (the hosting app for both cmd and powershell) so while i didn't test it, i'm not expecting much of a difference between powerhsell and cmd in this instance.

Richard Antalik commented

2020-06-16 21:31:21 +02:00

Added subscriber: @iss

Richard Antalik commented

2020-06-16 21:31:21 +02:00

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

Richard Antalik commented

2020-06-16 21:31:21 +02:00

I would like to somehow bisect this report.
@derekbarker can you upload sample .blend file that demonstrates this issue as clearly as possible? Is there some version where this issue have been introduced, or did this work well at some point in time?

I would like to somehow bisect this report. @derekbarker can you upload sample .blend file that demonstrates this issue as clearly as possible? Is there some version where this issue have been introduced, or did this work well at some point in time?

Ray molenkamp commented

2020-06-16 22:25:08 +02:00

cube_279.blend

Render time in seconds

version	ui	console	console to file	console to NUL
2.79	24.83	22.99	20.77	19.92
2.80	21.15	39.45	18.16	15.62
2.83	20.89	37.57	18.12	15.96

I don't think you are going to have a good time bisecting this, as the change is quite likely coming from the compiler (coughCRT*cough) change between 2.79 and 2.80

[cube_279.blend](https://archive.blender.org/developer/F8626445/cube_279.blend) Render time in seconds |version|ui|console|console to file|console to NUL| | -- | -- | -- | -- | -- | |2.79|24.83|22.99|20.77|19.92| |2.80|21.15|39.45|18.16|15.62| |2.83|20.89|37.57|18.12|15.96| I don't think you are going to have a good time bisecting this, as the change is quite likely coming from the compiler (*cough*CRT*cough) change between 2.79 and 2.80

Ray molenkamp commented

2020-06-16 22:55:11 +02:00

hmm interesting small repro case between 2013 and 2017 yields much better performance on 2017 not worse, so i can't just be the printing to the console from different threads, something else must have changed.

compiler	win10	win7
2013	609ms	842ms
2017	438ms	749ms

- include <Windows.h>
- include <stdio.h>

#define loops 1000
DWORD WINAPI MyThreadFunction(LPVOID lpParam)
{
	DWORD d = GetCurrentThreadId();
	for (int i = 0; i < loops; i++) {
		printf("%x Fra:1 Mem:49.59M (0.00M, Peak 49.77M) | Time:00:00.20 | Remaining:00:13.11 | Mem:1.60M, Peak:1.61M | Scene, RenderLayer | Rendered %d/%d Tiles\n", d, i, loops);
	}
	return 0;
}

#define MAX_THREADS 8

int main(int argc, char **argv)
{
	DWORD start = GetTickCount();
	DWORD   dwThreadIdArray[MAX_THREADS];
	HANDLE  hThreadArray[MAX_THREADS];
	for (int i = 0; i < MAX_THREADS; i++)
	{
		hThreadArray[i] = CreateThread(
			NULL,                   // default security attributes
			0,                      // use default stack size  
			MyThreadFunction,       // thread function name
			NULL,                   // argument to thread function 
			0,                      // use default creation flags 
			&dwThreadIdArray[i]);   // returns the thread identifier 
	}
	WaitForMultipleObjects(MAX_THREADS, hThreadArray, TRUE, INFINITE);
	DWORD endtick = GetTickCount();
	printf("total time = %d\n", endtick - start);
}```

hmm interesting small repro case between 2013 and 2017 yields much better performance on 2017 not worse, so i can't just be the printing to the console from different threads, something else must have changed. |compiler|win10|win7| | -- | -- | -- | |2013|609ms|842ms| |2017|438ms|749ms| ``` - include <Windows.h> - include <stdio.h> #define loops 1000 DWORD WINAPI MyThreadFunction(LPVOID lpParam) { DWORD d = GetCurrentThreadId(); for (int i = 0; i < loops; i++) { printf("%x Fra:1 Mem:49.59M (0.00M, Peak 49.77M) | Time:00:00.20 | Remaining:00:13.11 | Mem:1.60M, Peak:1.61M | Scene, RenderLayer | Rendered %d/%d Tiles\n", d, i, loops); } return 0; } #define MAX_THREADS 8 int main(int argc, char **argv) { DWORD start = GetTickCount(); DWORD dwThreadIdArray[MAX_THREADS]; HANDLE hThreadArray[MAX_THREADS]; for (int i = 0; i < MAX_THREADS; i++) { hThreadArray[i] = CreateThread( NULL, // default security attributes 0, // use default stack size MyThreadFunction, // thread function name NULL, // argument to thread function 0, // use default creation flags &dwThreadIdArray[i]); // returns the thread identifier } WaitForMultipleObjects(MAX_THREADS, hThreadArray, TRUE, INFINITE); DWORD endtick = GetTickCount(); printf("total time = %d\n", endtick - start); }```

Ray molenkamp commented

2020-06-17 06:09:06 +02:00

Added subscriber: @dr.sybren

Ray molenkamp commented

2020-06-17 06:09:06 +02:00

d2757d149b removed buffering on stdout, causing it to try and grab a lock on the console for every single character printed causing the regression.

Reverting it gives the following stats (Render time in seconds)

version	ui	console	console to file	console to NUL
2.79	24.83	22.99	20.77	19.92
2.80	21.15	39.45	18.16	15.62
2.83	20.89	37.57	18.12	15.96
master+revert	18.28	17.03	16.37	16.09

@dr.sybren mind if we wrap that in a #ifdef NDEBUG ? Willing to settle for an windows specific exclusion (kinda depending if someone can repro the regression on linux or not)

d2757d149b removed buffering on stdout, causing it to try and grab a lock on the console for every single character printed causing the regression. Reverting it gives the following stats (Render time in seconds) |version|ui|console|console to file|console to NUL| | -- | -- | -- | -- | -- | |2.79|24.83|22.99|20.77|19.92| |2.80|21.15|39.45|18.16|15.62| |2.83|20.89|37.57|18.12|15.96| |master+revert|18.28|17.03|16.37|16.09| @dr.sybren mind if we wrap that in a `#ifdef NDEBUG` ? Willing to settle for an windows specific exclusion (kinda depending if someone can repro the regression on linux or not)

blender-admin commented

2020-06-17 17:26:49 +02:00

This issue was referenced by 945e18f037

This issue was referenced by 945e18f037108c2767617ddba339e0f7938329d8

blender-admin commented

2020-06-17 17:26:49 +02:00

This issue was referenced by e590526af6

This issue was referenced by e590526af6e843cc173beb5ae06ac1d8c5fad471

Ray molenkamp commented

2020-06-17 17:27:13 +02:00

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

Ray molenkamp closed this issue

2020-06-17 17:27:13 +02:00

Ray molenkamp self-assigned this 2020-06-17 17:27:13 +02:00

Sybren A. Stüvel commented

2020-06-18 11:03:27 +02:00

Added subscriber: @Sergey

Sybren A. Stüvel commented

2020-06-18 11:03:27 +02:00

@Sergey do you have an opinion about this? I know that the Cycles logs are dear to you when we're rendering in Flamenco. I'm guessing that having multiple threads write to the console without mutex would cause them to jumble pretty badly?

Ray molenkamp commented

2020-06-18 13:42:50 +02:00

the problematic mutex is not inside blender, it's one the CRT manages itself, the NDEBUG solution chosen was @Sergey 's preference

Sergey Sharybin commented

2020-06-18 13:49:45 +02:00

@dr.sybren, as long as we stick to GLOG for logging we are good.

Sign in to join this conversation.

No Label

Download

What's New

Blender Studio

Manual

Developers Blog

Documentation

Benchmark

Blender Conference

Development Fund

One-time Donations

Slow Cycles CLI render with proper tile sizes #76767