CudaTimer in measuring forward rendering time

Gaming and Visualization Technologies Raytracing
1

Hi,

I have recently started a project on ray tracing using OptiX.

Exact function call looks something like this:
This can be found in the open source code base : 3dgrut/threedgrt_tracer/tracer.py at main · nv-tlabs/3dgrut · GitHub

(self.frame_timer is a CudaTimer)

    def render(self, gaussians, gpu_batch: Batch, train=False, frame_id=0):
        num_gaussians = gaussians.num_gaussians
        with torch.cuda.nvtx.range(f"model.forward({num_gaussians} gaussians)"):

            if self.frame_timer is not None:
                self.frame_timer.start()

            (pred_rgb, pred_opacity, pred_dist, pred_normals, hits_count, mog_visibility) = Tracer._Autograd.apply(
                self.tracer_wrapper,
                frame_id,
                gpu_batch.T_to_world.contiguous(),
                gpu_batch.rays_ori.contiguous(),
                gpu_batch.rays_dir.contiguous(),
                gaussians.positions.contiguous(),
                gaussians.get_rotation().contiguous(),
                gaussians.get_scale().contiguous(),
                gaussians.get_density().contiguous(),
                gaussians.get_features().contiguous(),
                Tracer.RenderOpts.DEFAULT,
                gaussians.n_active_features,
                self.conf.render.min_transmittance,
            )

            if self.frame_timer is not None:
                self.frame_timer.end()

            pred_rgb, pred_opacity = gaussians.background(
                gpu_batch.T_to_world.contiguous(), gpu_batch.rays_dir.contiguous(), pred_rgb, pred_opacity, train
            )

        if self.frame_timer is not None:
            self.timings["forward_render"] = self.frame_timer.timing()

        return {
            "pred_rgb": pred_rgb,
            "pred_opacity": pred_opacity,
            "pred_dist": pred_dist,
            "pred_normals": torch.nn.functional.normalize(pred_normals, dim=3),
            "hits_count": hits_count,
            "frame_time_ms": self.frame_timer.timing() if self.frame_timer is not None else 0.0,
            "mog_visibility": mog_visibility,
        }

When i measure this CudaTimer, value comes out to be lesser than the value shown in NVIDIA NSight Profiler in CUDA HW optixLaunch, by around 80ms. At the same time, time in nvtx range “model.forward({num_gaussians} gaussians)” comes out to be 60 micro seconds.

I want to understand what is CudaTimer measuring here? I know that optixLaunch could be asynchronous, but that would result CudaTimer to show very small value(in micro seconds)

I’m trying to experiment with forward rendering times, and trying to understand what is happening here. Any help would mean a lot to me. Thank you.

2

I’m not familiar with that code but three orders of magnitude difference is huge. The NVTX range in Nsight is only bracketing the duration of the call, which is asynchronous, not the duration of the CUDA kernel. Adding a synchronization should give a more meaningful duration (and stall the GPU, bad). CUDA timers give the duration of the kernel without overhead.

3

It looks like CudaTimer is inserting CUDA events into the stream, right?

That should capture the device-side kernel timings, so I think you’re right that it’s curious that it would come out smaller than the NVTX range.

I wonder if all the .contiguous() calls are doing something on a different stream? It’s a little bit difficult to look at Python that is calling Torch and understand what’s really happening on host & device, there are a lot of moving parts here. You also don’t have direct visibility into the OptiX NVTX events. One thing you could try is to wrap the CudaTimer start/stop in your own custom NVTX events, and you can see those in Nsight Systems. You can also study the Nsight Systems profile Timeline View to see if the additional time is visible.

You might be able to see Nsight Systems correllation events when you click on the optixLaunch bar in the “OptiX API” row in the Timeline view. For example I can see several CUDA API events that belong to the optixLaunch:

image
image899×110 3.93 KB

(BTW, this is an example profile of an OptiX SDK sample, not 3dgrut)

Let us know if a little more digging in the profile doesn’t help clarify what’s going on, and we can try it on our side and see if we spot the discrepancy. Is this from the main branch of 3dgrut? Can you summarize the repro steps?

–
David.

4

Issue is resolved now. Problem was with the code which prints this cuda timer. I can now see in the NSight Systems, forward_render_cuda timer comes out to be only slightly larger than optixLaunch time in Nsight. Thanks @dhart @lspano for your time and help.

Also,
contiguous calls were happening is the same stream, so that was not the issue.

5

Ah, thanks for the follow up! Very glad to hear the timer is better & making sense now.

–
David.