23. Debugging & Profiling

Written by Marius Horga

Debugging and Profiling are must-have skills for optimizing the performance of your projects, and Apple has provided developers with several fantastic optimization tools to achieve this. In this chapter, you’ll look at:

1. Debugging: Locate hard-to-find bugs using the GPU debugger.
2. Profiling: Monitor your app’s performance with Instruments and other tools.

Time to go on a bug hunt!

Debugging

Rather than trying to guess the truth, it’s always more useful to capture a GPU frame and examine it for clues.

The aim of this section is to render a scene similar to this:

In the starter folder, open the Debugging project. Build and run, and you’ll notice the rocks and grass are missing from the scene.

You’ll look into potential causes for why that happened, shortly.

Launch the Capture GPU Frame tool by clicking the camera button in the debug bar.

Debug navigator

After Xcode finishes capturing the GPU frame, it displays the debugger windows.

On the left side, you’ll see a GPU trace in the Debug navigator. The debugger always stops at the last encoder the command buffer commits, so select RenderCommandEncoder.

This is where you’ll see the command encoders within each command buffer.

Press Cmd Shift T or File ▸ New ▸ Window to open up a new window. In this new window, open Renderer.swift and locate draw(in:). With side-by-side windows, you can compare the code in draw(in:) with the commands listed in the debugger.

In this frame, you have one render command encoder that renders all of the elements of the scene, and one compute command encoder that doesn’t do anything yet. The debugger lists each command in the command encoder, such as setFragmentBytes and setComputePipeline.

It’s a good idea, as draw(in:) currently does, to surround each draw command with a debug group with renderEncoder.pushDebugGroup(renderable.name) as it gives a friendly name to each draw call, and you can easily see what items are rendering. In the debugger, you can see debug groups with ground.obj, grass and Rocks.

Close the new window when you have finished comparing the command list.

Central pane

The top middle area of the captured frame has the central pane that normally opens to the Dependency Viewer — a nice summary of the current command buffer.

On the right side, the assistant editor lists attachments and the Debug and Inspect Pixels buttons.

Attachments are the resources held by color and depth attachments.

Note: To see the attachments, you may have to choose Attachments from the top jump bar.

Debug area

The bottom area is the Debug area, and it has two larger areas — GPU States and Console — as well as the debug bar that hosts the Debug Shader and the Reload Shader buttons; You’ll use these a lot in your debugging career.

All right, time for debugging!

In the Debug navigator, open the Rocks group, and select drawIndexedPrimitives.

Bound Resources should automatically display in the central pane, and Attachments in the assistant editor pane, but you can also select these from the jump bars.

You can see in the Debug navigator that both Grass and Rocks are listed, and both of them have draw calls. This means that these models are rendered, but for some reason, they don’t appear on the screen. A logical next step is to look at how vertices are rendered.

The geometry viewer

While still having drawIndexedPrimitives for the Rocks group selected, click the Debug Shader icon on the debug bar, and select the Vertex pane. This is the Geometry Viewer tool.

Note: The shader debugger magically “knows” if you’re debugging a render encoder or a compute encoder and adapts its contents accordingly. For vertex shaders, it opens the Geometry Viewer. You can learn more about it on the Apple documentation web page at https://developer.apple.com/documentation/metal/vertex_data/inspecting_vertices_with_the_geometry_viewer.

Notice how the frustum only has a few vertices rendered for Rocks, and most of them are being skipped. A next logical step is to look at the shader code. There are two ways to go to your shader code:

• Double-click vertex_nature in the central pane to open the vertex shader in place (in the central pane).
• While in a shader debugger session, clicking Debug takes you to the shader code.

Note: When entering the shader debugger in your own Metal projects, you may get an error. To see the debugging information, you have to compile with shader source code included. You can do this in your project’s build settings. Under Produce Debugging Information, on the Debug option, switch to Yes, include source code. On the Release option, verify it’s set to No. Production apps are not allowed to contain debug information, so you wouldn’t want to leave your app with such info when publishing it later to the App Store.

Examining the code in the vertex shader, you realize that with this line:

VertexIn vertexIn = in[offset];

You’re reading only one vertex per offset value. What you should be doing is offsetting the vertex buffer index instead. Change the previous line to this:

VertexIn vertexIn = in[vertexID + offset];

On the debug bar, click Reload Shaders next to Debug Shader.

All of the vertices are now showing in the shader debugger.

You can use the central pane to display the Geometry Viewer. Click the Rocks group to expand it, and then select the draw call for the rocks. In the central pane, double-click Geometry and you’ll see a much more useful screen for exploring geometry.

You can drag to rotate, use the mouse scroll wheel, or pinch gestures for zooming, and use the mouse middle button for panning. You can also right click to show/hide other viewing options such as wireframe. You also get a bottom pane containing all of the relevant primitive’s vertex values. You can click any of the vertices to display it in the viewer.

The Geometry Viewer is handy for analyzing triangles. Are they visibly rendered incorrectly? Are they missing? Are they outside of the viewing frustum? And so on.

In the main app window, notice that you now have both the grass and the rocks showing in the scene.

That’s great! However, the rocks are missing their textures. Taking a quick look at the vertex structs, again in the vertex shader, notice there’s a uv member that’s not being passed through in the vertex shader. So, add this line before return:

out.uv = vertexIn.uv;

Click Reload Shaders again, and you’ll see that the rocks now have their textures.

The rocks look better now, but there’s something off about the lighting in the scene. The next logical step is to move to the fragment shader and investigate how the light is calculated.

Note: Changing shader functions in the shader debugger, as of the time of writing, does not update the functions in your code. They will revert to the original code after you finish running the app. Remember what you have changed to make your functions work, and re-enter the code in the shader functions when you have completed your debugging.

The pixel inspector

With the draw call in the Rocks group still selected, click Debug Shader again. This time, you’ll use the Inspect Pixels tool to look at the scene. You can, once again, confirm with the magnifier that the textures are indeed applied to rocks, because you can see other colors as well besides shades of grey.

The shader debugger

There are two ways to navigate to the fragment shader code. With the magnifier placed on an active fragment — i.e., one that is in the group currently being drawn — either:

• In the assistant editor pane, click Debug next to the Inspect Pixels tool. If the Debug button is grayed out, it means that the magnifier is not over one of the fragments currently being drawn. Drag the magnifier over a rock.
• In debug shader, click Debug, which takes you to the fragment shader code.

Just like a playground, the shader debugger shows you a snapshot of the calculations that make up the final fragment. When the fragment shader opens in the shader debugger, click the little square next to the line where diffuseIntensity is defined. This little square turns blue and opens a preview pane for the selected variable:

You immediately notice that the result of this calculation is incorrect because the value of this and surrounding pixels is a solid color. Diffuse intensity should be a value between 0 and 1. The color is red, as only the red channel is being used here, so 1.0 results in a solid red.

You also know from Chapter 5, “Lighting Fundamentals,” that to calculate diffuse light, you need to take the dot product of two vectors: the direction of light and the surface normal. If that did not make you say “A-ha!” then take another look at this line:

float3 sunlight = normalize(in.worldNormal);

All you need to do here is normalize the surface normal but a mistake must have been made in calling this variable sunlight when it should be named normal or something similar. It may have been confused with the constant vector named sunlight, which you use for lightDirection.

Change the previous line to:

float3 normal = normalize(in.worldNormal);

Then, update this line:

float diffuseIntensity = saturate(dot(lightDirection, 
                                      sunlight));

To use the proper normal vector:

float diffuseIntensity = saturate(dot(lightDirection, normal));

Click Reload Shaders on the debug bar and review the result:

The diffuse intensity is now properly calculated and contributing to the light in the scene. Look at the main app window to see:

As you look closely at it, you notice that the light is now so intense that it looks almost fluorescent. A next logical step is to examine how diffuseIntensity is being factored into the color calculation:

float4 color = mix(baseColor * 1.5, baseColor * 0.5, 
                   diffuseIntensity);

Looking at the line above, notice how the start and end values of the range in which to interpolate baseColor are reversed. Swap the two values:

float4 color = mix(baseColor * 0.5, baseColor * 1.5, 
                   diffuseIntensity);

Once again, click Reload Shaders.

Notice how the values changed in the preview pane for color.

You can also see that your final image now almost matches the one from the beginning of the chapter; almost, because the grass, rocks and trees are randomly positioned at every run. The skybox currently isn’t rendered in your app window either, because it renders after the rocks.

Note: Remember to update both vertex_nature and fragment_nature in Nature.metal with the changes you just made, once you stop the app.

GPU frame capture

There’s one more debugging feature that you’ll love and use a lot. You can trigger the GPU Capture Frame tool to start at a breakpoint!

As you know, you can’t put breakpoints inside shaders, but you can put them after the line where the CPU sends work to the GPU.

In Renderer.swift, in draw(in:), look for //compute debugging. You’re going to debug a compute pipeline this time so you can see how the shader debugger tool looks for compute too.

Place a new breakpoint after the command encoder ends encoding. Right-click the breakpoint and choose Edit Breakpoint. Click the Add Action button next to Action and from the Action drop-down, choose Capture GPU Frame.

Build and run the project. The breakpoint automatically starts a GPU frame capture. In the Debug navigator, with dispatchThreadgroups selected under the computer command encoder, click Debug Shader.

This shows you the most important variables you need: the number of threads per grid, the number of threads per threadgroup and the number of threadgroups per grid.

Select any thread id, and then click Debug to jump right to it in the shader debugger. Click on the little square next to the selected line of code to, once again, make use of the handy preview panes:

As you can see, you can follow each thread in real time and see how its values change throughout the kernel function. As in this example, clicking the third thread automatically selects it on the next two preview panes and updates the corresponding values on each of the affected lines.

The pid before any line executes has the value 1 for that thread, id gets updated to 2 on the first line, and finally, id gets updated again to 4 on the next line where it’s being multiplied.

By the way, you can also capture a GPU frame programmatically by using a MTLCaptureDescriptor object and setting its destination to either .developerTools if you want the capture to live inside Xcode, or .gpuTraceDocument if you want to write capture data to a file on disk.

Debugging is great for finding anomalies or missing content. However, what makes your app run even more content, and faster too, is profiling! You’ll be working on that next.

Remove the breakpoint from your app before continuing.

Profiling

Always profile early and do it often.

There are a few ways to monitor and tweak your app’s performance. You’ll be looking at each of these next.

GPU history

GPU history is a tool provided by the macOS operating system via its Activity Monitor app, so it is not inside Xcode. It shows basic GPU activity in real time for all of your GPUs. If you’re using eGPUs, it’ll show activity in there too.

Open Activity Monitor, and from the Window menu, choose GPU History; a window will pop up containing separate graphs for each GPU, showing the GPU usage in real time.

You can change how often the graph is updated from the View ▸ Update Frequency menu. The graph moves right-to-left at the frequency rate you set.

Here’s a screenshot taken from a MacBook Pro that has a discrete GPU — AMD Radeon Pro 450 — and an integrated one — Intel HD Graphics 530:

The system is using the integrated Intel GPU for regular tasks, and it switches to the discrete AMD GPU when running a graphics-intensive task such as this Xcode project you’re working on.

The GPU History tool offers a quick way to see overall GPU usage, but it’s not helpful with showing GPU usage for individual running apps and processes.

The GPU report

Build and run your app again, then capture a GPU frame. On the Debug navigator, click FPS gauge on the left side.

The GPU report shows in the central pane and contains three major GPU metrics.

The first GPU report metric is Frames Per Second and represents the current frame rate of your app. Your target should always be 60 FPS or better.

The second GPU report metric is Utilization which shows how busy your GPU is doing useful work. A healthy app will have the GPU always utilized to some extent. Having it sit idle might be an indication that the CPU has not given it enough work to do.

On iOS and tvOS devices, the GPU utilization is separated into geometry processing (tiler) and pixel processing (renderer). The third column includes both utilization values.

The third GPU report metric is Frame Time and represents the actual time spent processing the current frame on the CPU and the GPU. What’s most important here is that the frame does not take longer than 16.6ms which corresponds to 60 FPS.

Your app is running at 60 FPS (16.6ms), and the GPU is not sitting idle. So far so good!

The shader profiler

This is perhaps the most useful profiling tool for the shader code you are writing. It has nothing to do with the rendering code the CPU is setting up, or the passes you run or the resources you’re sending to the GPU. This tool tells you how your MSL code is performing line-by-line and how long it took to finish.

Unfortunately, the shader profiler shows you the individual line execution times (per-line cost) on iOS devices only.

Build and run the project on an iOS device this time, then capture a new GPU frame. In the Debug navigator, switch to View Frame By Performance using the View frame in different ways icon. You can now see how much time each pipeline took during the frame.

Note: Your times and percentages will vary depending on your iOS device, Xcode and iOS version.

The entire pipeline took 5.63ms to complete. That time consists of 2.04ms for the vertex shader and 3.59ms for the fragment shader.

Drilling down the cost tree, most of the fragment shader execution time is taken by the sample() function (1.86ms) and the normalize() function (1.34ms).

As soon as you select the pipeline, the central pane updates to show the shaders, and more importantly, a convenient column with times and percentages for the code lines that affect the cost the most.

The total time that the shader takes to complete shows on the function header line. Inside the shader for each impactful line, you’ll see the percentage the line took out of that total time. In the case of the sample() function on line 81, that 1.86ms correspond to 36.25% of the 3.24ms total shader time.

On iOS devices from the family 4 (iPhone X) or later, the shader profiler will even show you a pie chart with activities displayed as slices representing the total time an activity took to complete.

Hover over the colored dot to disclose the pie chart.

Analyze the percentages for each GPU activity. A high number might indicate an opportunity for performance optimization.

Looking at the various GPU activities and their percentages, notice how the ALU took 31.99% of the total shader time processing the various data types and calculations involving them.

Here’s the first opportunity for optimization using shader profiling. Notice that processing floats seems to take more time than processing other types. As you might know, a half is, well, half the size of a float, so you can optimize this one spot.

Change all of the floats to halfs everywhere in the fragment shader, as well as in the sunlight definition line above the fragment shader.

When done, click Reload Shaders. The pie chart will also update in real time, as well as the Attachments contents if you also have the assistant editor open.

Note: Reloading the shader might not save your changes so make sure to take a note of what you changed and later update Nature.metal manually.

Well, look at that! Not only did you eliminate the cost of processing Floats, but you also reduced the shader execution time from 8.17ms to only 7.35ms (almost 1ms gain). Great job for such a minor effort. Other ALU optimizations you can do includes replacing ints with shorts, simplifying complex instructions such as trigonometry functions (sin, cos, etc.) and other arithmetic calculations.

Next, you can look into Synchronization issues. The biggest concern here is the Wait Memory time which is taking almost a quarter of all the shader time (23.54%). This is happening because some instructions are waiting for dependent memory accesses that took place in previous instructions. The sample() function is a good candidate for this bottleneck because the mix() function heavily depends on it. You’ll deal with synchronization in the next chapter.

The next part, Memory, took 11% of the shader execution time. This represents the time sample() spent waiting for access to the texture memory. You can shorten this time by down-sampling the textures.

The final category, Control Flow, did not take any time all because you did not use conditionals, increments or branching instructions.

GPU Counters and Memory

The GPU Counters information panel is another profiling tool you can use for optimizing the performance of your command encoders.

To access the GPU Counters, capture a new GPU frame. In the Debug navigator, click the Counters gauge.

This automatically displays the Pipeline Activity Bar Chart in the center pane, while the assistant editor should update to show the Performance view. Choose Performance from the assistant editor jump bar, if it does not update. If the center pane has Encoder selected at the top, switch to Draw view:

These are general statistics broken down by render command encoders shown next to each other. You only have one render command encoder in this app. If you right click anywhere on the bar chart you get the option to Export GPU Counters as a CSV file to disk.

In the Debug navigator, select the draw call with the highest cost and expand it. Then, select Performance from the list. In the Counters column, observe the GPU counters for the encoder that contains the selected draw call.

Each of the columns gives you useful information about your draw calls. The total column values refer to all of the draws for the selected command encoder. The other values are per selected draw call. You can also get this data programmatically on macOS by calling the encoder’s sampleCounters method and by using a MTLCounterSampleBuffer object to store the counter data to.

In the Potential Hotspots/Bottlenecks section you’ll see optimization recommendations for the selected draw call based on the GPU Counters data.

One of the recommendations is Occlusion culling. Currently you’re rendering everything, no matter whether the camera can see it or not. If a rock is completely behind another rock, but is rendered first, then rendering that rock may be a waste of resources. One technique is to render objects forward to backward, as the rasterizer will automatically cull objects that have a greater z depth than previous objects. Another technique performs a separate render pass, checking bounding boxes and visibility.

Finally, click the Memory tool (below Counters) to see the total memory used and how the various resources are allocated in memory:

Pipeline statistics

Pipeline statistics is yet another profiling tool that tells you the number of instructions each of the GPU activities of your draw call is using.

Capture another GPU frame. In the Debug navigator, select the draw call with the highest cost and expand it, then select Pipeline Statistics from the list.

That opens the pipeline statistics informational panel in the central pane, containing Remarks at the top, graph bars for shader metrics in the center and related draw calls at the bottom.

Earlier, you replaced the fragment_nature() floats with half, but the profiler informs you that you will increase performance if you repeat that for the vertex function too.

Dependency viewer

The Dependency Viewer is one of the new tools introduced at WWDC 2018, along with the Shader Debugger and the Geometry Viewer.

Capture another GPU frame. In the Debug navigator, select your command buffer or a command encoder and see the dependency viewer in the central pane.

You can see the render and compute command encoders as a hierarchical flowchart. It’s easier to see multiple dependencies in this view than looking at the call list in the Debug navigator. The dependencies can quickly get crowded, however.

This is the dependency chart for the final project from Chapter 14, “Multipass & Deferred Rendering.”

Using its visual layout, it’s easy to identify redundant command encoders or passes that you could have missed in the code or in the draw calls list.

For each command encoder in the graph, you’ll see the execution time, the number of draw calls, the bound resources and, based on the type of the encoder, either the number of vertices processed or the number of thread dispatches. A line going to another command encoder indicates dependency for it.

Metal System Trace

The last and most essential profiling tool is the Metal System Trace (MST) which is a specialized Instruments template for Metal. There are two ways of launching an MST session:

• Build and run your app in Xcode. Launch the Instruments app and from the profiling templates window, choose Metal System Trace. In the Instruments window, from the devices list, choose your Mac and then your running app you want to profile.

• While in Xcode, instead of building and running your app, choose Product ▸ Profile. This will open Instruments. Choose the Metal System Trace template or the Game Performance template and then Instruments will auto-select your running app.

Either way you choose, the next step applies to both approaches. Click the big red dot on the top left side of Instruments.

This starts recording your app running in windowed mode. After about 10 seconds or so, stop the recording and review the results.

In the bottom pane, if you select the GPU instrument, you can see which GPU was used more than the others (AMD Radeon Pro 450 here).

Using the Option key, and your mouse or pinch gesture, you can zoom in and out of areas of interest.

Close the Instruments window without saving it, and open GrassScene.swift. You’ll stress the app by increasing the number of grass blades rendered. Change:

setupGrass(instanceCount: 50000, width: 10, depth: 10)

To:

setupGrass(instanceCount: 400000, width: 10, depth: 10)

Run the app, and check the frames per second on the Debug navigator. You’re looking for around 50-55 fps. Change instanceCount to suit your device. You may need to increase or decrease it to get similar results.

Now stop the app, and choose Product ▸ Profile to run Instruments. Choose Metal System Trace and press the Record button at the top left. Press the right arrow to rotate in a full circle, then stop the profiling using the Stop button at the top left.

At the top left of the Detail area, click Metal Encoder Hierarchy and change it to Observations.

The Observations category lists a number of Display issues. You’ll notice that in the Built-in Display trace (or if you’re running several monitors, then whichever monitor holds the app), there are a lot of exclamation marks in circles in the Stutters row. These correspond to the Display issues listed in the Observations:

Surface was displayed for 33.33ms on Display.

This message means the drawable is being held for longer than desired (16.66ms). One indication might be the fact that the drawable was acquired too quickly by the command buffer.

On the console list, you can click any entry, and it takes you to that frame on the graph bars.

Your app is currently trying to achieve 60 frames per second. When you run the app at 50 fps, you’ll get stutters as indicated in this Metal System Trace. If you can’t improve your frames per second, a last resort method is to lower the expected fps from 60 to a number that you can achieve every single frame. This will mean a lower fps, but the visuals will be smoother.

Open Renderer.swift, and in init(metalView:), immediately after the guard statement, and before assigning the static variables, add this:

metalView.preferredFramesPerSecond = 30

Profile the app with instruments again, and turn a complete circle using the right arrow key. You may notice that the action is smoother.

When you profile the app, many of the Display observations will have disappeared. You’ll still have stuttering on loading the app, but once it’s fully loaded, the game should run smoothly.

The largest gaps are between two consecutive frames. You can see on the Metal Application graphs bars that the render encoder finishes its work before the frame ends.

You can take at least two actions here. First, you should synchronize the CPU and GPU shared access to resources. Second, you should run your encoders on multiple threads.

In the next chapter, you’ll be working on taking your project to a highly parallelized state.

Where to go from here?

The path to optimal performance is not trivial, and it’s going to be a journey full of trial and error experiments. Where debugging is a science, profiling is a work of art. Experiment, take a step back, look at it, go back and tweak some more. In the end, it’s all going to be worth the effort.

In the next chapter, you will learn how to optimize the performance of your application, taking your project to a highly parallelized state, and always staying on top of the Metal best practices.