Performance – Why Does `perf stat` Show 0 Context Switches?

Older versions of perf ~2.6.x

I'm using perf version: 2.6.35.14-106.

Capture all the output

I don't have the -x switch on my Fedora 14 system so I'm not sure if that's your actual problem or not. I'll investigate on a newer Ubuntu 12.10 system later on but this worked for me:

$ (perf stat -ecache-misses ls ) > stat.log 2>&1
$
$ more stat.log 
maccheck.txt
sample.txt
stat.log

 Performance counter stats for 'ls':

              13209  cache-misses            

        0.018231264  seconds time elapsed

I only want perf's output

You could try this, the output from ls will get redirected to /dev/null. The output form perf (both STDERR and STDOUT) goes to the file, stat.log.

$ (perf stat -ecache-misses ls > /dev/null ) > stat.log 2>&1
[saml@grinchy 89576]$ more stat.log 

 Performance counter stats for 'ls':

              12949  cache-misses            

        0.022831281  seconds time elapsed

Newer versions of perf 3.x+

I'm using perf version: 3.5.7

Capturing only perf's output

With the newer versions of perf there are dedicated options for controlling where messages get sent. You have the choice of either sending them to a file via the -o|--output option. Simply give either of those switches a filename to capture the output.

-o file, --output file
    Print the output into the designated file.

The alternative is to redirect the output to a alternate file descriptor, 3, for example. All you need to do is direct this alternate file handle prior to streaming to it.

--log-fd
    Log output to fd, instead of stderr. Complementary to --output, and 
    mutually exclusive with it. --append may be used here. Examples: 
       3>results perf stat --log-fd 3  — $cmd
       -or-
       3>>results perf stat --log-fd 3 --append — $cmd

So if we wanted to collect the perf output for the ls command you could use this command:

$ 3>results.log perf stat --log-fd 3 ls > /dev/null
$ 
$ more results.log

 Performance counter stats for 'ls':

          2.498964 task-clock                #    0.806 CPUs utilized          
                 0 context-switches          #    0.000 K/sec                  
                 0 CPU-migrations            #    0.000 K/sec                  
               258 page-faults               #    0.103 M/sec                  
           880,752 cycles                    #    0.352 GHz                    
           597,809 stalled-cycles-frontend   #   67.87% frontend cycles idle   
           652,087 stalled-cycles-backend    #   74.04% backend  cycles idle   
         1,261,424 instructions              #    1.43  insns per cycle        
                                             #    0.52  stalled cycles per insn [55.31%]
     <not counted> branches                
     <not counted> branch-misses           

       0.003102139 seconds time elapsed

If you use the --append version then the contents of multiple commands will be appended to the same log file, results.log in our case.

Installing perf

Installation is pretty trivial:

Fedora

$ yum install perf

Ubuntu/Debian

$ apt-get install linux-tool-common linux-tools

References

• System wide profiling
• Tracing on Linux
• perf: Linux profiling with performance counters
• Counting with perf stat

I know this question is pretty old (Feb 16) but here a response in case it helps someone else. The problem is that you've entered the '-F 999' indicating that you want to sample the events at a frequency of 999 times a second. For 'trace' events, you don't generally want to do sampling. For instance, when I select sched:sched_switch, I want to see every context switch. If you enter -F 999 then you will get a sampling of the context switches... If you look at the output of your 'perf record' cmd with something like:

perf script --verbose -I --header -i perf.dat -F comm,pid,tid,cpu,time,period,event,trace,ip,sym,dso > perf.txt

then you would see that the 'period' (the number between the timestamp and the event name) would not (usually) be == 1.

If you use a 'perf record' cmd like below, you'll see a period of 1 in the 'perf script' output like:

Binder:695_5   695/2077  [000] 16231.700440:          1         sched:sched_switch: prev_comm=Binder:695_5 prev_pid=2077 prev_prio=120 prev_state=S ==> next_comm=kworker/u16:17 next_pid=7665 next_prio=120

A long winded explanation but basically: don't do that (where 'that' is '-F 999').

If you just do something like:

perf record -a -g -e sched:sched_switch -e sched:sched_blocked_reason -e sched:sched_stat_sleep -e sched:sched_stat_wait sleep 5

then the output would show every context switch with the call stack for each event. And you might need to do:

echo 1 > /proc/sys/kernel/sched_schedstats

to get the sched_stat events.