perf сообщает о нескольких событиях sched: sched_stat_sleep для одного сна - PullRequest
Новая
       11

perf сообщает о нескольких событиях sched: sched_stat_sleep для одного сна

3 голосов
/ 14 мая 2019

Я пытался профилировать пример приложения 

#include<stdio.h>
#include<unistd.h>

int calculate() {
        int i=0, ret;
        for(i=0;i<10000000;i++) {
                ret +=i;
        }
        return ret;
}

int main(int argc, char ** ch) {
        int loop;
        for(loop=0; loop<5; loop++){
                sleep(1);
                calculate();
        }
}

Я использовал perf запись для профилирования. 

perf record -e sched:sched_stat_sleep -e sched:sched_switch -o perfnoallcpu.data -g ./loop

Я вижу, что для каждого коммутатора есть 4 sched: sched_stat_sleep сообщается. 

 swapper     0/0     [000]   222.777113:    1269841 sched:sched_stat_sleep: comm=perf pid=2927 delay=1269841 [ns]
         swapper     0/0     [000]   222.777116:    1269841 sched:sched_stat_sleep: comm=perf pid=2927 delay=1269841 [ns]
         swapper     0/0     [000]   222.777117:    1269841 sched:sched_stat_sleep: comm=perf pid=2927 delay=1269841 [ns]
         swapper     0/0     [000]   222.777118:    1269841 sched:sched_stat_sleep: comm=perf pid=2927 delay=1269841 [ns]
            loop  2927/2927  [001]   222.777651:          1 sched:sched_switch: prev_comm=loop prev_pid=2927 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120
         swapper     0/0     [001]   223.777227:  999577599 sched:sched_stat_sleep: comm=loop pid=2927 delay=999577599 [ns]
         swapper     0/0     [001]   223.777230:  999577599 sched:sched_stat_sleep: comm=loop pid=2927 delay=999577599 [ns]
         swapper     0/0     [001]   223.777231:  999577599 sched:sched_stat_sleep: comm=loop pid=2927 delay=999577599 [ns]
         swapper     0/0     [001]   223.777232:  999577599 sched:sched_stat_sleep: comm=loop pid=2927 delay=999577599 [ns]
            loop  2927/2927  [001]   223.803313:          1 sched:sched_switch: prev_comm=loop prev_pid=2927 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120
         swapper     0/0     [001]   224.802882:  999568643 sched:sched_stat_sleep: comm=loop pid=2927 delay=999568643 [ns]
         swapper     0/0     [001]   224.802884:  999568643 sched:sched_stat_sleep: comm=loop pid=2927 delay=999568643 [ns]
         swapper     0/0     [001]   224.802885:  999568643 sched:sched_stat_sleep: comm=loop pid=2927 delay=999568643 [ns]
         swapper     0/0     [001]   224.802885:  999568643 sched:sched_stat_sleep: comm=loop pid=2927 delay=999568643 [ns]
            loop  2927/2927  [001]   224.814909:  999483089 sched:sched_stat_sleep: comm=kworker/1:1 pid=65 delay=999483089 [ns]
            loop  2927/2927  [001]   224.814913:          1 sched:sched_switch: prev_comm=loop prev_pid=2927 prev_prio=120 prev_state=R ==> next_comm=kworker/1:1 next_pid=65 next_prio=120
            loop  2927/2927  [001]   224.828492:          1 sched:sched_switch: prev_comm=loop prev_pid=2927 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120
         swapper     0/0     [001]   225.828066:  999572687 sched:sched_stat_sleep: comm=loop pid=2927 delay=999572687 [ns]
         swapper     0/0     [001]   225.828069:  999572687 sched:sched_stat_sleep: comm=loop pid=2927 delay=999572687 [ns]
         swapper     0/0     [001]   225.828070:  999572687 sched:sched_stat_sleep: comm=loop pid=2927 delay=999572687 [ns]
         swapper     0/0     [001]   225.828071:  999572687 sched:sched_stat_sleep: comm=loop pid=2927 delay=999572687 [ns]
            loop  2927/2927  [001]   225.829873:  301152896 sched:sched_stat_sleep: comm=compiz pid=1723 delay=301152896 [ns]
            loop  2927/2927  [001]   225.829877:          1 sched:sched_switch: prev_comm=loop prev_pid=2927 prev_prio=120 prev_state=R ==> next_comm=compiz next_pid=1723 next_prio=120
            loop  2927/2927  [001]   225.853764:          1 sched:sched_switch: prev_comm=loop prev_pid=2927 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120
         swapper     0/0     [001]   226.853341:  999576357 sched:sched_stat_sleep: comm=loop pid=2927 delay=999576357 [ns]
         swapper     0/0     [001]   226.853343:  999576357 sched:sched_stat_sleep: comm=loop pid=2927 delay=999576357 [ns]
         swapper     0/0     [001]   226.853344:  999576357 sched:sched_stat_sleep: comm=loop pid=2927 delay=999576357 [ns]
         swapper     0/0     [001]   226.853345:  999576357 sched:sched_stat_sleep: comm=loop pid=2927 delay=999576357 [ns]
            loop  2927/2927  [001]   226.878867:          1 sched:sched_switch: prev_comm=loop prev_pid=2927 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120
         swapper     0/0     [001]   227.878442:  999573760 sched:sched_stat_sleep: comm=loop pid=2927 delay=999573760 [ns]
         swapper     0/0     [001]   227.878443:  999573760 sched:sched_stat_sleep: comm=loop pid=2927 delay=999573760 [ns]
         swapper     0/0     [001]   227.878444:  999573760 sched:sched_stat_sleep: comm=loop pid=2927 delay=999573760 [ns]
         swapper     0/0     [001]   227.878445:  999573760 sched:sched_stat_sleep: comm=loop pid=2927 delay=999573760 [ns]

количество sched_stat_sleep увеличивается с увеличением числа процессоров.Это делает приложение более длительным сном.

Если я укажу опцию -a при выполнении perf-записи, проблема исчезнет, ​​мы увидим только одно событие sched_stat_sleep за один сон.

1 Ответ

3 голосов
/ 14 мая 2019

Это ошибка в ядре, которая влияет и на другие события (сообщение от chengjian (D) показывает, что оно влияет на sched:sched_stat_sleep).По-видимому, событие подсчитывается столько раз, сколько имеется процессоров (nrcpus).Согласно this diff, исправление включено в версию ядра 4.18.17 (которая гарантирует, что событие засчитывается только для процессора, на котором оно произошло.

...