Hey @Aprecigout,
so, I had a look at your scene. For me it runs in under 0.4 seconds on each run. I did not use your code though. You do some things which are not fast when you look at the context of your document (which has 30k frames), such as, for example, printing a line for all 30k frames. But your timings do not include these calls, so they should not be reflected and certainly also not cause an increase over multiple runs (as Python simply starts to truncate its console at some point). Also, the BUILDFLAGS_EXPORTONLY
flag is a bit questionable in your context, but it should make things faster and not slower. My tests are with the more common case of no build flags (but I also tried your flag, and things were slightly faster).
Not unloading the document and operating in the active document are the likely causes for the difference, except for your measuring being faulty somehow. But even ignoring this does not really explain your numbers. I used one of our builtin profiling tools, the mxutils.TIMEIT
decorator.
There is of course also some difference between the timings of my calls, but with 0.355 sec, 0.360 sec, 0359 sec, ..., it is well within a to be expected variance of 5% for something as complex as scene execution.
Cheers,
Ferdinand
edit: And for good measure, I also set the count to 50
, and executing the passes for the 48th, 49th, and 50th time took 0.362 sec, 0.355 sec, and 0.350 sec for me. So, even over much more repetitions nothing significant happens for me.
Result
--------------------------------------------------------------------------------
TIMEIT: Ran 'ExecutePasses((<c4d.documents.BaseDocument object called with ID 110059 at 6327756096>, 30, 0, 34200), {})' with 68406 function calls in 0.355 seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.013 0.013 0.355 0.355 .../untitled 19.py:6(ExecutePasses)
34201 0.338 0.000 0.338 0.000 {method 'ExecutePasses' of 'c4d.documents.BaseDocument' objects}
34201 0.004 0.000 0.004 0.000 {method 'SetTime' of 'c4d.documents.BaseDocument' objects}
1 0.000 0.000 0.000 0.000 .../python311/mxutils/mxu_base.py:107(CheckType)
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
1 0.000 0.000 0.000 0.000 {built-in method builtins.isinstance}
--------------------------------------------------------------------------------
TIMEIT: Ran 'ExecutePasses((<c4d.documents.BaseDocument object called with ID 110059 at 22211370816>, 30, 0, 34200), {})' with 68406 function calls in 0.360 seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.013 0.013 0.360 0.360 .../untitled 19.py:6(ExecutePasses)
34201 0.340 0.000 0.340 0.000 {method 'ExecutePasses' of 'c4d.documents.BaseDocument' objects}
34201 0.006 0.000 0.006 0.000 {method 'SetTime' of 'c4d.documents.BaseDocument' objects}
1 0.000 0.000 0.000 0.000 .../python311/mxutils/mxu_base.py:107(CheckType)
1 0.000 0.000 0.000 0.000 {built-in method builtins.isinstance}
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
--------------------------------------------------------------------------------
TIMEIT: Ran 'ExecutePasses((<c4d.documents.BaseDocument object called with ID 110059 at 22211397440>, 30, 0, 34200), {})' with 68406 function calls in 0.359 seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.012 0.012 0.359 0.359 .../untitled 19.py:6(ExecutePasses)
34201 0.342 0.000 0.342 0.000 {method 'ExecutePasses' of 'c4d.documents.BaseDocument' objects}
34201 0.005 0.000 0.005 0.000 {method 'SetTime' of 'c4d.documents.BaseDocument' objects}
1 0.000 0.000 0.000 0.000 .../python311/mxutils/mxu_base.py:107(CheckType)
1 0.000 0.000 0.000 0.000 {built-in method builtins.isinstance}
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
--------------------------------------------------------------------------------
TIMEIT: Ran 'ExecutePasses((<c4d.documents.BaseDocument object called with ID 110059 at 22211328064>, 30, 0, 34200), {})' with 68406 function calls in 0.373 seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.012 0.012 0.373 0.373 .../untitled 19.py:6(ExecutePasses)
34201 0.356 0.000 0.356 0.000 {method 'ExecutePasses' of 'c4d.documents.BaseDocument' objects}
34201 0.005 0.000 0.005 0.000 {method 'SetTime' of 'c4d.documents.BaseDocument' objects}
1 0.000 0.000 0.000 0.000 .../python311/mxutils/mxu_base.py:107(CheckType)
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
1 0.000 0.000 0.000 0.000 {built-in method builtins.isinstance}
--------------------------------------------------------------------------------
TIMEIT: Ran 'ExecutePasses((<c4d.documents.BaseDocument object called with ID 110059 at 22211401792>, 30, 0, 34200), {})' with 68406 function calls in 0.366 seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.013 0.013 0.366 0.366 .../untitled 19.py:6(ExecutePasses)
34201 0.347 0.000 0.347 0.000 {method 'ExecutePasses' of 'c4d.documents.BaseDocument' objects}
34201 0.005 0.000 0.005 0.000 {method 'SetTime' of 'c4d.documents.BaseDocument' objects}
1 0.000 0.000 0.000 0.000 .../python311/mxutils/mxu_base.py:107(CheckType)
1 0.000 0.000 0.000 0.000 {built-in method builtins.isinstance}
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
Code
"""Provides a short example for how to execute the passes on all frames of a document, multiple times
in a row, while measuring the time it takes to execute the passes.
"""
import c4d
import mxutils
# A debug variable to control whether we want to see debug output or not and the file we are going
# to load and profile over and over again.
#
# Always use a global constant such as IS_DEBUG when using the mxutils.TIMEIT decorator, as the
# overhead especially for profiling (compared to pure timing) can be quite high. Profiling should
# NEVER leak into production code! With a global constant, this is much more unlikely to happen.
IS_DEBUG: bool = True
FILE_PATH: str = "/Users/f_hoppe/Downloads/user_scene.c4d"
@mxutils.TIMEIT(enabled=IS_DEBUG, useProfiler=True, showArgs=True)
def ExecutePasses(doc: c4d.documents.BaseDocument, fps: int, minFrame: int, maxFrame: int) -> None:
"""Executes the passes for the given document in the given frame range.
"""
mxutils.CheckType(doc, c4d.documents.BaseDocument)
for f in range(minFrame, maxFrame + 1):
doc.SetTime(c4d.BaseTime(f, fps))
doc.ExecutePasses(None, True, True, True, c4d.BUILDFLAGS_EXPORTONLY)
def main() -> None:
"""Called by Cinema 4D to execute the script.
"""
doc: c4d.documents.BaseDocument | None = None
# We just iterate five times over the same document, to see if there are any slowdowns.
for i, p in enumerate([FILE_PATH] * 5):
# Unload the current document if it exists and then load the new one.
if isinstance(doc, c4d.documents.BaseDocument):
c4d.documents.KillDocument(doc)
doc: c4d.documents.BaseDocument = c4d.documents.LoadDocument(p, c4d.SCENEFILTER_NONE)
c4d.gui.StatusSetText(f"Building passes for document {i + 1}/5.")
# Execute the passes for the loaded document with our custom function which uses the
# mxutils.TIMEIT decorator to profile the event.
fps: int = doc.GetFps()
minFrame: int = doc[c4d.DOCUMENT_MINTIME].GetFrame(fps)
maxFrame: int = doc[c4d.DOCUMENT_MAXTIME].GetFrame(fps)
ExecutePasses(doc, fps, minFrame, maxFrame)
c4d.gui.StatusClear()
c4d.EventAdd()
if __name__ == '__main__':
main()