Run 'Perf Stat' on The Output of 'Perf Record'

Perf Stat vs Perf Record

First of all, your test case of using sleep and page-faults is not an ideal test case. There should be no page fault events during the sleep duration, you you can't really expect anything interesting. For the sake of easier reasoning I suggest to use the ref-cycles (hardware) event and a busy workload such as awk 'BEGIN { while(1){} }'.

Question 1: It is my understanding that perf stat gets a "summary" of
counts but when used with the -I option gets the counts at the
specified millisecond interval. With this option does it sum up the
counts over the interval or get the average over the interval, or
something else entirely? I assume it is summed up.

Yes. The values are just summed up. You can confirm that by testing:

$ perf stat -e ref-cycles -I 1000 timeout 10s awk 'BEGIN { while(1){} }'
#           time             counts unit events
 1.000105072      2,563,666,664      ref-cycles                                                  
 2.000267991      2,577,462,550      ref-cycles                                                  
 3.000415395      2,577,211,936      ref-cycles                                                  
 4.000543311      2,577,240,458      ref-cycles                                                  
 5.000702131      2,577,525,002      ref-cycles                                                  
 6.000857663      2,577,156,088      ref-cycles                                                  

[ ... snip ... ]
[ Note that it may not be as nicely consistent on all systems due dynamic frequency scaling ]

$ perf stat -e ref-cycles -I 3000 timeout 10s awk 'BEGIN { while(1){} }' 
#           time             counts unit events
 3.000107921      7,736,108,718      ref-cycles                                                  
 6.000265186      7,732,065,900      ref-cycles                                                  
 9.000372029      7,728,302,192      ref-cycles     

Question 2: Why doesn't perf stat -e <event1> -I 1000 sleep 5 give
about the same counts as if I summed up the counts over each second
for the following command perf record -e <event1> -F 1000 sleep 5?

perf stat -I is in milliseconds, whereas perf record -F is in HZ (1/s), so the corresponding command to perf stat -I 1000 is perf record -F 1. In fact with our more stable event/workload, this looks better:

$ perf stat -e ref-cycles -I 1000 timeout 10s awk 'BEGIN { while(1){} }'
#           time             counts unit events
 1.000089518      2,578,694,534      ref-cycles                                                  
 2.000203872      2,579,866,250      ref-cycles                                                  
 3.000294300      2,579,857,852      ref-cycles                                                  
 4.000390273      2,579,964,842      ref-cycles                                                  
 5.000488375      2,577,955,536      ref-cycles                                                  
 6.000587028      2,577,176,316      ref-cycles                                                  
 7.000688250      2,577,334,786      ref-cycles                                                  
 8.000785388      2,577,581,500      ref-cycles                                                  
 9.000876466      2,577,511,326      ref-cycles                                                  
10.000977965      2,577,344,692      ref-cycles                                                  
10.001195845            466,674      ref-cycles    

$ perf record -e ref-cycles -F 1 timeout 10s awk 'BEGIN { while(1){} }'
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.008 MB perf.data (17 samples) ]

$ perf script -F time,period        
3369070.273722:          1 
3369070.273755:          1 
3369070.273911:       3757 
3369070.273916:    3015133 
3369070.274486:          1 
3369070.274556:          1 
3369070.274657:       1778 
3369070.274662:    2196921 
3369070.275523: 47192985748 
3369072.663696: 2578692405 
3369073.663547: 2579122382 
3369074.663609: 2580015300 
3369075.664085: 2579873741 
3369076.664433: 2578638211 
3369077.664379: 2578378119 
3369078.664175: 2578166440 
3369079.663896: 2579238122 

So you see, eventually the results are stable also for perf record -F. Unfortunately the documentation of perf record is very poor. You can learn what the settings -c and -F mean by looking at the documentation of the underlying system call man perf_event_open:

sample_period, sample_freq A "sampling" event is one that
generates an overflow notification every N events, where N is given by
sample_period. A sampling event has sample_period > 0. When
an overflow occurs, requested data is recorded in the mmap buffer.
The sample_type field controls what data is recorded on each
overflow.

sample_freq can be used if you wish to use frequency rather than
period. In this case, you set the freq flag. The kernel will
adjust the sampling period to try and achieve the desired rate. The
rate of adjustment is a timer tick.

So while perf stat uses an internal timer to read the value of the counter every -i milliseconds, perf record sets an event overflow counter to take a sample every -c events. That means it takes a sample every N events (e.g. every N page-fault or cycles). With -F, it it tries to regulate this overflow value to achieve the desired frequency. It tries different values and tunes it up/down accordingly. This eventually works for counters with a stable rate, but will get erratic results for dynamic events.

Redirect perf ouput

Probably the process you attached to didn't generate any events during the interval perf was running for. For example if it was asleep and never woke up.

In that case, you get <not counted> for each event where perf didn't even record a start point, e.g. no context switch to the process. (perf stat still can record and print 0 for an event, so <not counted> means something more than 0. Although for events like task-clock or cycles it's essentially synonymous because there's no way for those events not to count any counts or time while a process is running.)

This all applies regardless of whether perf was outputting to the terminal and killed with control-C, or outputting to a file with -o. (Just tested it on my desktop with the PID of a chromium process that apparently didn't do anything in the 2 seconds I left perf running.)

But anyway, you should treat <not collected> as 0, or a sign that you didn't sample long enough to see anything interesting.

Related Topics