How to interpret go pprof/mutex showing waiting on Unlock?

Question

I'm optimizing Go program performance. While looking at mutex profiling, I got

> go tool pprof -seconds 30 -ignore .*Shopify.*  http://HOST/debug/pprof/mutex
(pprof) top 20
Active filters:
ignore=.*Shopify.*
Showing nodes accounting for 3.08mins, 91.03% of 3.39mins total
Dropped 82 nodes (cum <= 0.02mins)
    flat  flat%   sum%        cum   cum%
3.08mins 91.03% 91.03%   3.08mins 91.03%  sync.(*Mutex).Unlock
       0     0% 91.03%   0.06mins  1.75%  ....func2
       0     0% 91.03%   0.06mins  1.75%  ....func3

Code snippet is

     .          .    502:    w.mu.Lock()

     .          .    ... some calculation

     .   5.02mins    510:    w.mu.Unlock()
     .          .    511:
     .          .    512:    return nil
     .          .    513:}

What I don't understand are:

• Why mutex profiling shows only top 1 has flat time, all the rest are 0?
• If it shows waiting on Lock then it probably means calculation takes too long, but what does it mean when it shows waiting on Unlock?

Answer 1

To answer your second question, mutex profiles always display results on the Unlock path, and never on Lock [1]. Your profile is indicating that most contention is occurring on w.mu.

This document contains a bit more detail.

[1] Implementation detail: the reason for this is that Unlock hands off the lock to the next waiting locker, and it is at this point that the contention is recorded in the profile. Thus the stack trace appears to be in the Unlock path.