Merge pull request #1381 from uragirii/slowest-frame

packages/cli/src/render.tsx

@@ -321,10 +321,18 @@ export const render = async (remotionRoot: string) => {
 		puppeteerInstance,
 		onDownload,
 		downloadMap,
+		onSlowestFrames: (slowestFrames) => {
+			Log.verbose();
+			Log.verbose(`Slowest frames:`);
+			slowestFrames.forEach(({frame, time}) => {
+				Log.verbose(`Frame ${frame} (${time.toFixed(3)}ms)`);
+			});
+		},
 	});
 
 	Log.info();
 	Log.info();
+
 	const seconds = Math.round((Date.now() - startTime) / 1000);
 	Log.info(
 		[

packages/docs/docs/renderer/render-frames.md

@@ -39,11 +39,25 @@ const onStart = () => {
 
 ### `onFrameUpdate`
 
-A callback function that gets called whenever a frame finished rendering. An argument is passed containing how many frames have been rendered (not the frame number of the rendered frame). Example value
+A callback function that gets called whenever a frame finished rendering. An argument is passed containing how many frames have been rendered (not the frame number of the rendered frame).
+
+In `v3.0.0`, a second argument was added: `frame`, returning the frame number that was just rendered.
+
+In `v3.2.30`, a third argument was rendered: `timeToRenderInMilliseconds`, describing the time it took to render that frame in milliseconds.
 
 ```ts twoslash
-const onFrameUpdate = (frame: number) => {
-  console.log(`${frame} frames rendered.`);
+const onFrameUpdate = (
+  framesRendered: number,
+  frame: number,
+  timeToRenderInMilliseconds: number
+) => {
+  console.log(`${framesRendered} frames rendered.`);
+
+  // From v3.0.0
+  console.log(`${frame} was just rendered.`);
+
+  // From v3.2.30
+  console.log(`It took ${timeToRenderInMilliseconds}ms to render that frame.`);
 };
 ```
 

packages/docs/docs/renderer/render-media.md

@@ -377,6 +377,30 @@ _available from v3.2.29_
 
 Disallows the renderer from doing rendering frames and encoding at the same time. This makes the rendering process more memory-efficient, but possibly slower.
 
+### `onSlowestFrames?`
+
+_available from v3.2.29_
+
+Callback function that gets called right before `renderMedia()` resolves.  
+The only argument `slowestFrames` is an array of the 10 slowest frames in the shape of `{frame:<Frame number>, time:<Time to render frame ms>}`. You can use this information to optimise your render times.
+
+```tsx twoslash
+import type { OnSlowestFrames } from "@remotion/renderer";
+
+const onSlowestFrames: OnSlowestFrames = (slowestFrames) => {
+  console.log("The slowest 10 frames are:");
+  for (const slowFrame of slowestFrames) {
+    console.log(`Frame ${slowFrame.frame} (${slowFrame.time}ms)`);
+  }
+};
+```
+
+## Return Value
+
+_since v3.0.26_
+
+If `outputLocation` is not specified or `null`, the return value is a Promise that resolves a `Buffer`. If an output location is specified, the return value is a Promise that resolves no value.
+
 ## See also
 
 - [Source code for this function](https://github.com/remotion-dev/remotion/blob/main/packages/renderer/src/render-media.ts)

packages/lambda/src/functions/renderer.ts

@@ -199,6 +199,13 @@ const renderHandler = async (
 			downloadMap,
 			muted: params.muted,
 			enforceAudioTrack: true,
+			onSlowestFrames: (slowestFrames) => {
+				console.log();
+				console.log(`Slowest frames:`);
+				slowestFrames.forEach(({frame, time}) => {
+					console.log(`Frame ${frame} (${time.toFixed(3)}ms)`);
+				});
+			},
 		})
 			.then(() => resolve())
 			.catch((err) => reject(err));

packages/renderer/src/index.ts

@@ -95,9 +95,11 @@ export {PixelFormat} from './pixel-format';
 export {ProResProfile} from './prores-profile';
 export {renderFrames} from './render-frames';
 export {
+	OnSlowestFrames,
 	renderMedia,
 	RenderMediaOnProgress,
 	RenderMediaOptions,
+	SlowFrame,
 	StitchingState,
 } from './render-media';
 export {renderStill, RenderStillOptions} from './render-still';

packages/renderer/src/render-frames.ts

@@ -1,5 +1,6 @@
 import fs from 'fs';
 import path from 'path';
+import {performance} from 'perf_hooks';
 import type {SmallTCompMetadata, TAsset} from 'remotion';
 import {Internals} from 'remotion';
 import type {RenderMediaOnDownload} from './assets/download-and-map-assets-to-file';
@@ -68,7 +69,11 @@ type ConcurrencyOrParallelism =
 
 type RenderFramesOptions = {
 	onStart: (data: OnStartData) => void;
-	onFrameUpdate: (framesRendered: number, frameIndex: number) => void;
+	onFrameUpdate: (
+		framesRendered: number,
+		frameIndex: number,
+		timeToRenderInMilliseconds: number
+	) => void;
 	outputDir: string | null;
 	inputProps: unknown;
 	envVariables?: Record<string, string>;
@@ -290,6 +295,8 @@ const innerRenderFrames = ({
 				throw new Error('Render was stopped');
 			}
 
+			const startTime = performance.now();
+
 			const errorCallbackOnFrame = (err: Error) => {
 				onError(err);
 			};
@@ -372,7 +379,7 @@ const innerRenderFrames = ({
 			});
 			pool.release(freePage);
 			framesRendered++;
-			onFrameUpdate(framesRendered, frame);
+			onFrameUpdate(framesRendered, frame, performance.now() - startTime);
 			cleanupPageError();
 			freePage.off('error', errorCallbackOnFrame);
 			return compressedAssets;

packages/renderer/src/render-media.ts

@@ -48,6 +48,11 @@ import {validateScale} from './validate-scale';
 
 export type StitchingState = 'encoding' | 'muxing';
 
+const SLOWEST_FRAME_COUNT = 10;
+
+export type SlowFrame = {frame: number; time: number};
+export type OnSlowestFrames = (frames: SlowFrame[]) => void;
+
 export type RenderMediaOnProgress = (progress: {
 	renderedFrames: number;
 	encodedFrames: number;
@@ -94,6 +99,7 @@ export type RenderMediaOptions = {
 	muted?: boolean;
 	enforceAudioTrack?: boolean;
 	ffmpegOverride?: FfmpegOverrideFn;
+	onSlowestFrames?: OnSlowestFrames;
 	disallowParallelEncoding?: boolean;
 } & ServeUrlOrWebpackBundle &
 	ConcurrencyOrParallelism;
@@ -156,6 +162,7 @@ export const renderMedia = ({
 	muted,
 	enforceAudioTrack,
 	ffmpegOverride,
+	onSlowestFrames,
 	...options
 }: RenderMediaOptions): Promise<Buffer | null> => {
 	validateQuality(options.quality);
@@ -321,13 +328,48 @@ export const renderMedia = ({
 	const mediaSupport = codecSupportsMedia(codec);
 	const disableAudio = !mediaSupport.audio || muted;
 
+	const slowestFrames: SlowFrame[] = [];
+	let maxTime = 0;
+	let minTime = 0;
+
+	const recordFrameTime = (frameIndex: number, time: number) => {
+		const frameTime: SlowFrame = {frame: frameIndex, time};
+
+		if (time < minTime && slowestFrames.length === SLOWEST_FRAME_COUNT) {
+			return;
+		}
+
+		if (time > maxTime) {
+			// add at starting;
+			slowestFrames.unshift(frameTime);
+			maxTime = time;
+		} else {
+			// add frame at appropriate position
+			const index = slowestFrames.findIndex(
+				({time: indexTime}) => indexTime < time
+			);
+			slowestFrames.splice(index, 0, frameTime);
+		}
+
+		if (slowestFrames.length > SLOWEST_FRAME_COUNT) {
+			slowestFrames.pop();
+		}
+
+		minTime = slowestFrames[slowestFrames.length - 1]?.time ?? minTime;
+	};
+
 	const happyPath = createPrestitcherIfNecessary()
 		.then(() => {
 			const renderFramesProc = renderFrames({
 				config: composition,
-				onFrameUpdate: (frame: number) => {
+				onFrameUpdate: (
+					frame: number,
+					frameIndex: number,
+					timeToRenderInMilliseconds
+				) => {
 					renderedFrames = frame;
 					callUpdate();
+					recordFrameTime(frameIndex, timeToRenderInMilliseconds);
 				},
 				concurrency,
 				outputDir,
@@ -428,6 +470,8 @@ export const renderMedia = ({
 			encodedFrames = getFramesToRender(realFrameRange, everyNthFrame).length;
 			encodedDoneIn = Date.now() - stitchStart;
 			callUpdate();
+			slowestFrames.sort((a, b) => b.time - a.time);
+			onSlowestFrames?.(slowestFrames);
 			return buffer;
 		})
 		.catch((err) => {