metal : need help debugging a kernel and setting up Xcode

[ggerganov]

Recently, we found out that we can run the Metal code in debug mode with shader validation enabled:

make -j tests && MTL_DEBUG_LAYER=1 MTL_SHADER_VALIDATION=1 MTL_SHADER_VALIDATION_REPORT_TO_STDERR=1 MTL_SHADER_VALIDATION_FAIL_MODE=allow MTL_DEBUG_LAYER_VALIDATE_STORE_ACTIONS=1 MTL_DEBUG_LAYER_VALIDATE_LOAD_ACTIONS=1 ./tests/test-backend-ops -b Metal -o MUL_MAT

This has been a useful way to debug the Metal shaders in ggml-metal.metal. The above command runs the ggml_mul_mat operator in isolation and compares the results with the reference CPU result.

The result from the command without MTL_SHADER_VALIDATION=1 is success.
However, when the shader validation instrumentation is enabled, we get some NaNs:

The failures are produced by the matrix-matrix multiplication kernel:

• invoked here:
  https://github.com/ggerganov/llama.cpp/blob/328b83de23b33240e28f4e74900d1d06726f5eb1/ggml-metal.m#L1481-L1520
• implemented here:
  https://github.com/ggerganov/llama.cpp/blob/328b83de23b33240e28f4e74900d1d06726f5eb1/ggml-metal.metal#L3788-L3920

I've been trying to figure out what is causing the NaNs, but without success, so I'm calling for help from people that are more familiar with the Metal debugging pipeline and environment.

Currently, I think that this is somehow a false-positive because we've never observed an error and this kernel is used a lot. But still, I would very much like to make the Metal Validator happy.

I am reading on the internet that there should be a way to make a capture of this kernel and somehow debug it in Xcode, but I am not able to figure out exactly how. I was able to create an Xcode project with:

mkdir build-xcode
cd build-xcode
cmake -G Xcode ..

This allows me to run the test-backend-ops tool in Xcode in Debug mode.
I can also enable "Shader Validation" from the UI:

But that is as far as I've gotten. I cannot figure out how to capture some additional data in order to debug the source of these NaNs.

To isolate the tool to a single kernel call, you can apply this patch:

diff --git a/tests/test-backend-ops.cpp b/tests/test-backend-ops.cpp
index f04b9438..7e363912 100644
--- a/tests/test-backend-ops.cpp
+++ b/tests/test-backend-ops.cpp
@@ -1506,22 +1506,23 @@ static bool test_backend(ggml_backend_t backend, test_mode mode, const char * op
     for (ggml_type type_a : all_types) {
         for (ggml_type type_b : {GGML_TYPE_F32 /*, GGML_TYPE_F16 */}) {
             // FIXME: CPU crashes on f16xf16
-            test_cases.emplace_back(new test_mul_mat(type_a, type_b, 16, 1, 256, { 1,  1}, {1, 1}));
-            test_cases.emplace_back(new test_mul_mat(type_a, type_b, 16, 1, 256, {10,  1}, {1, 1}));
-            test_cases.emplace_back(new test_mul_mat(type_a, type_b, 16, 1, 256, {10,  1}, {2, 1}));
-            test_cases.emplace_back(new test_mul_mat(type_a, type_b, 16, 1, 256, {10, 10}, {1, 1}));
-            test_cases.emplace_back(new test_mul_mat(type_a, type_b, 16, 1, 256, {10, 10}, {2, 1}));
-            test_cases.emplace_back(new test_mul_mat(type_a, type_b, 16, 1, 256, {10, 10}, {1, 2}));
-            test_cases.emplace_back(new test_mul_mat(type_a, type_b, 16, 1, 256, {10, 10}, {2, 2}));
+            //test_cases.emplace_back(new test_mul_mat(type_a, type_b, 16, 1, 256, { 1,  1}, {1, 1}));
+            //test_cases.emplace_back(new test_mul_mat(type_a, type_b, 16, 1, 256, {10,  1}, {1, 1}));
+            //test_cases.emplace_back(new test_mul_mat(type_a, type_b, 16, 1, 256, {10,  1}, {2, 1}));
+            //test_cases.emplace_back(new test_mul_mat(type_a, type_b, 16, 1, 256, {10, 10}, {1, 1}));
+            //test_cases.emplace_back(new test_mul_mat(type_a, type_b, 16, 1, 256, {10, 10}, {2, 1}));
+            //test_cases.emplace_back(new test_mul_mat(type_a, type_b, 16, 1, 256, {10, 10}, {1, 2}));
+            //test_cases.emplace_back(new test_mul_mat(type_a, type_b, 16, 1, 256, {10, 10}, {2, 2}));
 
             test_cases.emplace_back(new test_mul_mat(type_a, type_b, 16, 16, 256, { 1,  1}, {1, 1}));
-            test_cases.emplace_back(new test_mul_mat(type_a, type_b, 16, 16, 256, {10,  1}, {1, 1}));
-            test_cases.emplace_back(new test_mul_mat(type_a, type_b, 16, 16, 256, {10,  1}, {2, 1}));
-            test_cases.emplace_back(new test_mul_mat(type_a, type_b, 16, 16, 256, {10, 10}, {1, 1}));
-            test_cases.emplace_back(new test_mul_mat(type_a, type_b, 16, 16, 256, {10, 10}, {2, 1}));
-            test_cases.emplace_back(new test_mul_mat(type_a, type_b, 16, 16, 256, {10, 10}, {1, 2}));
-            test_cases.emplace_back(new test_mul_mat(type_a, type_b, 16, 16, 256, {10, 10}, {2, 2}));
+            //test_cases.emplace_back(new test_mul_mat(type_a, type_b, 16, 16, 256, {10,  1}, {1, 1}));
+            //test_cases.emplace_back(new test_mul_mat(type_a, type_b, 16, 16, 256, {10,  1}, {2, 1}));
+            //test_cases.emplace_back(new test_mul_mat(type_a, type_b, 16, 16, 256, {10, 10}, {1, 1}));
+            //test_cases.emplace_back(new test_mul_mat(type_a, type_b, 16, 16, 256, {10, 10}, {2, 1}));
+            //test_cases.emplace_back(new test_mul_mat(type_a, type_b, 16, 16, 256, {10, 10}, {1, 2}));
+            //test_cases.emplace_back(new test_mul_mat(type_a, type_b, 16, 16, 256, {10, 10}, {2, 2}));
         }
+        break;
     }
 
     for (ggml_type type_a : all_types) {

Any help on this would be very appreciated. Even if it is just information of how to setup Xcode so that I can obtain some extra debug information.

cc @jhen0409 @bachittle or anyone else, thanks!

[bachittle]

Yea I know I was running into issues as well with trying to get debug information out of the metal code. To get the code to work in general I had to compile with -O3. I wonder if there is some bug that gets optimized away when running in a release build, and part of optimizing away is setting some NDEBUG flags.

[pudepiedj]

@ggerganov On the fools rush in ... principle, I thought I'd have a look at this, and running your command-line I get much the same errors on an M2 MAX 32GB (38 Core), so I put the whole command line into a shell script so that it would be easy to isolate separate elements,

make -j tests
MTL_DEBUG_LAYER=1
MTL_SHADER_VALIDATION=1
MTL_SHADER_VALIDATION_REPORT_TO_STDERR=1
MTL_SHADER_VALIDATION_FAIL_MODE=allow
MTL_DEBUG_LAYER_VALIDATE_STORE_ACTIONS=1
MTL_DEBUG_LAYER_VALIDATE_LOAD_ACTIONS=1
./tests/test-backend-ops -b Metal -o MUL_MAT

and when I ran it I didn't get any of the MUL_MAT errors (here or anywhere else) and the whole test passed:

 MUL_MAT(type_a=f32,type_b=f32,m=16,n=1,k=256,bs=[1,1],nr=[1,1]): OK
  MUL_MAT(type_a=f32,type_b=f32,m=16,n=1,k=256,bs=[10,1],nr=[1,1]): OK
  MUL_MAT(type_a=f32,type_b=f32,m=16,n=1,k=256,bs=[10,1],nr=[2,1]): OK
  MUL_MAT(type_a=f32,type_b=f32,m=16,n=1,k=256,bs=[10,10],nr=[1,1]): OK
  MUL_MAT(type_a=f32,type_b=f32,m=16,n=1,k=256,bs=[10,10],nr=[2,1]): OK
  MUL_MAT(type_a=f32,type_b=f32,m=16,n=1,k=256,bs=[10,10],nr=[1,2]): OK
  MUL_MAT(type_a=f32,type_b=f32,m=16,n=1,k=256,bs=[10,10],nr=[2,2]): OK
[rows missed out]
  704/704 tests passed
  Backend Metal: OK

This may be completely spurious, but I thought it might conceivably mean more to you than it does to me and it suggests your suspicion about false negatives may be right. Apologies if it's a red-herring.

[ggerganov]

You have to change your script to this:

make -j tests
export MTL_DEBUG_LAYER=1
export MTL_SHADER_VALIDATION=1
export MTL_SHADER_VALIDATION_REPORT_TO_STDERR=1
export MTL_SHADER_VALIDATION_FAIL_MODE=allow
export MTL_DEBUG_LAYER_VALIDATE_STORE_ACTIONS=1
export MTL_DEBUG_LAYER_VALIDATE_LOAD_ACTIONS=1
./tests/test-backend-ops -b Metal -o MUL_MAT

Else the environment variables won't stick

[pudepiedj]

Ah! And then the errors all come back. Thanks. Sorry to waste your time.

[pudepiedj]

@ggerganov In a (probably futile) attempt to make some small reparation for wasting your time on this earlier, I've been checking out how test-backend-ops works and where the [MUL-MAT] errors arise. My experiments suggest that all the following are true:

1. On my system there are always exactly 53 errors generating 656/709 test successes.
2. All the NaN errors occur in the f1 vector.
3. They all occur after the call to tensor_to_float (iow checking for NaN before the tensor_to_float(t1) call doesn't identify any NaNs).
4. Since t1 is an address-pointer, it's odd - if only to me - that it decreases by 2000 after the first run whereas t2 doesn't. Memory misalignment?
5. The t1 pointer (after the decrease mentioned above) increments by 800 per run whereas t2 increments by 400 per run, yet they are both supposed to be of the same type and size.
6. Some of the tests (usually just one per test) generate an NMSE error.

Since something is generating NaNs (always 00 00 C0 7F), how is it that in the call to tensor_to_float(t1) we change what looks like a perfectly-well-generated random test tensor without NaNs into something containing NaNs? Maybe that is just the question you were asking for help with, but this is for what it's worth, even if not much!

[ggerganov]

@pudepiedj Thanks for looking into this. I think I just found a solution after long trail and error. It seemed like the NaNs are bogus, so I started playing with Metal compile flags and found out that if I build the Metal code with -fno-fast-math -fno-inline the errors during shader validation disappear. I will push a fix via #4705 in a few days

[pudepiedj]

@pudepiedj Thanks for looking into this. I think I just found a solution after long trail and error. It seemed like the NaNs are bogus, so I started playing with Metal compile flags and found out that if I build the Metal code with -fno-fast-math -fno-inline the errors during shader validation disappear. I will push a fix via #4705 in a few days
That's great. Thanks for letting me know. I wouldn't have found that solution/workaround in 1000 years. I wonder whether it indicates a bug in the Metal code somewhere and what the performance implications might be, if any. Anyway, well done!