title: Ubuntu, how to find hotspot of program with heavy kernel work? It seems function at kernel.kallsyms doesn't mark as user space function's children
body: <p>Multi-thread program with heavy kernel work( lock unlock), try to find the hot spot at my code use profiling tools. </p>
  
  <p>I wrote a minimum reproducible program. Compile it. Use profiling tool such as perf , gprof with callstack record. None of then can report the hot spot at my code, but report function at kernel or libstdc++.so.</p>
  
  <pre><code>#include &lt;iostream&gt;
  #include &lt;mutex&gt;
  #include &lt;thread&gt;
  #include &lt;memory&gt;
  #include &lt;vector&gt;
  
  std::mutex mtx;
  long long_val = 0;
  
  void do_something(long &amp;val)
  {
      std::unique_lock&lt;std::mutex&gt; lck(mtx);
      for(int j=0; j&lt;1000; ++j)
          val++;
  }
  
  
  void thread_func()
  {
      for(int i=0; i&lt;1000000L; ++i)
      {
          do_something(long_val);
      }
  }
  
  
  int main(int argc, char* argv[])
  {
      std::vector&lt;std::unique_ptr&lt;std::thread&gt;&gt; threads;
      for(int i=0; i&lt;100; ++i)
      {
          threads.push_back(std::move(std::unique_ptr&lt;std::thread&gt;(new std::thread(thread_func))));
      }
      for(int i=0; i&lt;100; ++i)
      {
          threads[i]-&gt;join();
      }
      threads.clear();
      std::cout &lt;&lt; long_val &lt;&lt; std::endl;
      return 0;
  }
  </code></pre>
  
  <p>As we can se, <code>do_something()</code> is my program's hot spot. because too much of unique_lock cost lots of kernel work, and 1000 times of inc operate at the function. </p>
  
  <p><b>I want profiling tool tell me that, It is do_something() make a lot of lock, cause lots of kernel work. but from <code>perf</code>, I only can found it is lock slow down my code, but where made these lock operates at my code? it is not clear.</b></p>
  
  <p>Compile:</p>
  
  <p><code>g++ -o a.out -O3 -std=c++11 -fno-omit-frame-pointer -pthread -pg main.cpp</code></p>
  
  <p>Run program<code>./a.out</code>, htop report kernel taken half of CPU resource.</p>
  
  <p>Perf record:</p>
  
  <p><code>perf record -g ./a.out</code></p>
  
  <p>Perf report:</p>
  
  <pre><code>      Children      Self  Command  Shared Object        Symbol
      -   98.64%     0.00%  a.out    libstdc++.so.6.0.21  [.] 0x00000000000b8c80
         - 0xb8c80
            + 41.80% __lll_unlock_wake
            + 35.39% __lll_lock_wait
          12.77% pthread_mutex_lock
          7.69% pthread_mutex_unlock
          0.70% _Z11thread_funcv
      -   49.21%     0.88%  a.out    [kernel.kallsyms]    [k] entry_SYSCALL_64_after_hwframe
         + 48.33% entry_SYSCALL_64_after_hwframe
           0.88% 0xb8c80
      -   47.64%     1.06%  a.out    [kernel.kallsyms]    [k] do_syscall_64
         + 46.59% do_syscall_64
         + 1.06% 0xb8c80
      -   47.18%     1.44%  a.out    [kernel.kallsyms]    [k] sys_futex
         + 45.74% sys_futex
         + 1.44% 0xb8c80
      -   45.55%     1.65%  a.out    [kernel.kallsyms]    [k] do_futex
         + 43.90% do_futex
         + 1.65% 0xb8c80
      -   41.80%     1.30%  a.out    libpthread-2.23.so   [.] __lll_unlock_wake
         + 40.50% __lll_unlock_wake
         + 1.30% 0xb8c80
      -   35.39%     4.53%  a.out    libpthread-2.23.so   [.] __lll_lock_wait
         + 30.86% __lll_lock_wait
         + 4.53% 0xb8c80
      -   20.51%     5.40%  a.out    [kernel.kallsyms]    [k] futex_wake
         + 15.11% futex_wake
         + 5.40% 0xb8c80
      -   19.41%     0.88%  a.out    [kernel.kallsyms]    [k] futex_wait
         + 18.53% futex_wait
         + 0.88% 0xb8c80
      -   16.92%     6.25%  a.out    [kernel.kallsyms]    [k] _raw_spin_lock
         + 10.67% _raw_spin_lock
         + 6.25% 0xb8c80
      -   12.77%    12.73%  a.out    libpthread-2.23.so   [.] pthread_mutex_lock
           12.73% 0xb8c80
          pthread_mutex_lock
      +   11.80%     5.41%  a.out    [kernel.kallsyms]    [k] futex_wait_setup
      +   11.05%    11.05%  a.out    [kernel.kallsyms]    [k] syscall_return_via_sysret
      +   10.68%    10.67%  a.out    [kernel.kallsyms]    [k] native_queued_spin_lock_slowpath
      +    7.69%     7.65%  a.out    libpthread-2.23.so   [.] pthread_mutex_unlock
      +    7.36%     0.11%  a.out    [kernel.kallsyms]    [k] wake_up_q
      +    7.17%     1.27%  a.out    [kernel.kallsyms]    [k] try_to_wake_up
      +    4.42%     0.23%  a.out    [kernel.kallsyms]    [k] futex_wait_queue_me
      +    4.17%     0.08%  a.out    [kernel.kallsyms]    [k] schedule
      +    3.84%     0.75%  a.out    [kernel.kallsyms]    [k] __schedule
      +    2.70%     0.01%  a.out    [kernel.kallsyms]    [k] ttwu_do_activate
      +    2.49%     2.48%  a.out    [kernel.kallsyms]    [k] get_futex_value_locked
      +    2.38%     0.11%  a.out    [kernel.kallsyms]    [k] activate_task
      +    2.26%     0.15%  a.out    [kernel.kallsyms]    [k] enqueue_task_fair
      +    1.88%     1.88%  a.out    [unknown]            [k] 0xfffffe000000601b
      +    1.84%     0.15%  a.out    [kernel.kallsyms]    [k] __task_rq_lock
      +    1.78%     1.78%  a.out    [unknown]            [k] 0xfffffe000005e01b
      +    1.77%     1.77%  a.out    [unknown]            [k] 0xfffffe000003201b
      +    1.67%     0.02%  a.out    [kernel.kallsyms]    [k] deactivate_task
      +    1.66%     1.66%  a.out    [unknown]            [k] 0xfffffe000008a01b  
  </code></pre>
  
  <p><b>How can I use a profiling tool, to figure out this type hot spot at my really program. I don't want use "binary chop comment" to solve it every time. Thanks!</b></p>