Как использовать инструменты Google Perf

TL;DR: foo слишком быстро и мало для получения событий профилирования, запустите его еще 100 раз. В настройке частоты была опечатка, и pprof не будет сэмплировать чаще, чем CONFIG_HZ (обычно 250). Лучше перейти на более современный perf профайлер Linux (учебник от его авторов, Википедия).

Длинная версия:

Ваша функция foo слишком короткая и простая — просто вызовите две функции. Скомпилировал тест с g++ test.cc -lprofiler -o test.s -S -g, с фильтрацией test.s с c++filt программой, чтобы сделать имена c++ читабельными:

foo():
.LFB972:
        .loc 1 27 0
        pushq   %rbp
        movq    %rsp, %rbp
        .loc 1 28 0
        movl    $.LC0, %esi
        movl    std::cout, %edi
        call    std::basic_ostream<char, std::char_traits<char> >& std::operator<< <std::char_traits<char> >(std::basic_ostream<char, std::char_traits<char> >&, char const*)
        movl    std::basic_ostream<char, std::char_traits<char> >& std::endl<char, std::char_traits<char> >(std::basic_ostream<char, std::char_traits<char> >&), %esi
        movq    %rax, %rdi
        call    std::basic_ostream<char, std::char_traits<char> >::operator<<(std::basic_ostream<char, std::char_traits<char> >& (*)(std::basic_ostream<char, std::char_traits<char> >&))
        .loc 1 29 0
        popq    %rbp
        ret
.LFE972:
        .size   foo(), .-foo()

Итак, чтобы увидеть это в профиле, вы должны запустить foo больше раз, изменив int a = 1000; в main на что-то гораздо большее, например, 10000 или лучше 100000 (как я сделал для теста).

Также вы можете исправить неверный "CPUPROFILE_FREQUENC=10000", чтобы исправить CPUPROFILE_FREQUENCY (обратите внимание на Y). Я должен сказать, что 10000 слишком высокое значение для CPUPROFILE_FREQUENCY, потому что обычно оно может генерировать только 1000 или 250 событий в секунду в зависимости от конфигурации ядра CONFIG_HZ (большинство ядер 3.x имеют 250, проверьте grep CONFIG_HZ= /boot/config*). И значение по умолчанию для CPUPROFILE_FREQUENCY в pprof равно 100.

Я протестировал различные значения CPUPROFILE_FREQUENCY: 100000, 10000, 1000, 250 с помощью сценария bash в Ubuntu 14.04.

for a in 100000 100000 10000 10000 1000 1000 300 300 250 250; do 
   echo -n "$a "; 
   CPUPROFILE_FREQUENCY=$a CPUPROFILE=dump$a.txt ./test >/dev/null;
done

И результаты были те же 120-140 событий и время выполнения каждого ./test около 0,5 секунды, поэтому cpuprofiler из google-perftools не может делать больше событий в секунду для одного потока, чем CONFIG_HZ установлено в ядре (у меня 250).

100000 PROFILE: interrupts/evictions/bytes = 124/1/6584
100000 PROFILE: interrupts/evictions/bytes = 134/0/7864
10000 PROFILE: interrupts/evictions/bytes = 125/0/7488
10000 PROFILE: interrupts/evictions/bytes = 123/0/6960
1000 PROFILE: interrupts/evictions/bytes = 134/0/6264
1000 PROFILE: interrupts/evictions/bytes = 125/2/7272
300 PROFILE: interrupts/evictions/bytes = 137/2/7984
300 PROFILE: interrupts/evictions/bytes = 126/0/7216
250 PROFILE: interrupts/evictions/bytes = 123/3/6680
250 PROFILE: interrupts/evictions/bytes = 137/2/7352

С оригинальным a=1000 foo и функциями cout работают слишком быстро, чтобы получить какое-либо событие профилирования (даже при 250 событиях/с) для них при каждом запуске, поэтому у вас нет ни foo, ни каких-либо функций ввода/вывода. При небольшом количестве запусков __write_nocancel может получить событие выборки, а затем будет сообщено о foo и функциях ввода-вывода из libstdc++ (где-то не в самом верху, поэтому используйте параметр --text для pprof или google-pprof) с нулевым счетчиком собственных событий, и ненулевое количество дочерних событий:

 ....
   1   0.9%  99.1%        1   0.9% __write_nocancel
 ....
   0   0.0% 100.0%        1   0.9% _IO_new_file_overflow
   0   0.0% 100.0%        1   0.9% _IO_new_file_write
   0   0.0% 100.0%        1   0.9% __GI__IO_putc
   0   0.0% 100.0%        1   0.9% foo
   0   0.0% 100.0%        1   0.9% new_do_write
   0   0.0% 100.0%        1   0.9% std::endl
   0   0.0% 100.0%        1   0.9% std::ostream::put

С a=100000 foo по-прежнему слишком короткий и быстрый, чтобы получать собственные события, но функции ввода-вывода получили несколько. Это список, который я собрал из длинного вывода --text:

  34  24.6%  24.6%       34  24.6% __write_nocancel

   1   0.7%  95.7%       35  25.4% __GI__IO_fflush
   1   0.7%  96.4%        1   0.7% __GI__IO_putc
   1   0.7%  97.8%        2   1.4% std::operator<< 
   1   0.7%  98.6%       36  26.1% std::ostream::flush
   1   0.7%  99.3%        2   1.4% std::ostream::put
   0   0.0% 100.0%       34  24.6% _IO_new_file_sync
   0   0.0% 100.0%       34  24.6% _IO_new_file_write
   0   0.0% 100.0%       40  29.0% foo

   0   0.0% 100.0%       34  24.6% new_do_write

   0   0.0% 100.0%        2   1.4% std::endl

Функции с нулевыми собственными счетчиками видны только благодаря pprof возможности чтения цепочек вызовов (знает, кто вызывает функции, получившие выборку, если информация о кадре не опущена).

Я также могу порекомендовать более современный, более функциональный (как программные, так и аппаратные события, частота до 5 кГц и более; как профилирование пользовательского пространства, так и ядра) и лучше поддерживаемый профилировщик, профайлер Linux perf (руководство от авторов, википедия).

Есть результаты от perf с a=10000:

$ perf record  ./test3  >/dev/null
 ... skip some perf's spam about inaccessibility of kernel symbols 
 ... note the 3 kHz frequency here VVVV
Lowering default frequency rate to 3250. 
Please consider tweaking /proc/sys/kernel/perf_event_max_sample_rate.
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.078 MB perf.data (~3386 samples) ]

Чтобы увидеть текстовый отчет из выходного файла perf.data, я буду использовать меньше (потому что perf report по умолчанию запускает интерактивный браузер профилей):

$ perf report |less
... skip some extra info about the machine, kernel, and perf starting command
# Samples: 1K of event 'cycles'
# Event count (approx.): 1155264208
# Overhead   Command   Shared Object          Symbol
    41.94%    test3  libm-2.19.so         [.] __tan_sse2                                                                                                                                                                    
    16.95%    test3  libm-2.19.so         [.] __sin_sse2    
    13.40%    test3  libm-2.19.so         [.] __cos_sse2                                                                                                                                                                    
     4.93%    test3  test3                [.] bar()                                                                                                                                                                         
     2.90%    test3  libc-2.19.so         [.] __GI___libc_write    
....
     0.20%    test3  test3                [.] foo()                                                                                                                                                                         

Или perf report -n | less для просмотра необработанных счетчиков событий (выборок):

# Overhead       Samples  Command        Shared Object 
    41.94%           663    test3  libm-2.19.so         [.] __tan_sse2                                                                                                                                                                    
    16.95%           268    test3  libm-2.19.so         [.] __sin_sse2   
    13.40%           212    test3  libm-2.19.so         [.] __cos_sse2                                                                                                                                                                    
     4.93%            78    test3  test3                [.] bar()                                                                                                                                                                         
     2.90%            62    test3  libc-2.19.so         [.] __GI___libc_write     
 ....
     0.20%             4    test3  test3                [.] foo()                                                                                                                                                                         

Попробуйте установить LD_PRELOAD просто

LD_PRELOAD=/usr/local/lib/libprofiler.so

похоже, есть проблемы при передаче общей библиотеки, которая не заканчивается суффиксом .так.