Redirect perf ouput

Question

I am writing a performance monitoring script to monitor an application. Within this script, perf is called and then the application waits for a while before killing the perf process and gathering the perf information as well as other non-perf metrics. I am running the perf command by calling:

os.popen('perf stat -d -p ' + pid_executable + ' -o DATA/perf_stat.txt &')

I later kill this perf call with:

os.popen('kill -INT ' + pid_perf)

The -o option is to output the regular stdout to a file. Unfortunately, when kill is called none of the information is collected. The output is as follows:

# started on Tue Oct  5 22:28:43 2021


 Performance counter stats for process id '8056':

     <not counted>      task-clock                                                  
     <not counted>      context-switches                                            
     <not counted>      cpu-migrations                                              
     <not counted>      page-faults                                                 
     <not counted>      cycles                                                      
     <not counted>      instructions                                                
     <not counted>      branches                                                    
     <not counted>      branch-misses                                               
     <not counted>      L1-dcache-loads                                             
     <not counted>      L1-dcache-load-misses                                       
     <not counted>      LLC-loads                                                   
     <not counted>      LLC-load-misses                                             

       0.382097310 seconds time elapsed

Some events weren't counted. Try disabling the NMI watchdog:
    echo 0 > /proc/sys/kernel/nmi_watchdog
    perf stat ...
    echo 1 > /proc/sys/kernel/nmi_watchdog

My perf version is: perf version 3.10.0-957.12.1.el7.x86_64.debug

I have tried using environment variables to hold the output and redirecting using pipes, tee, and >, but this has yielded similar results. I do not have access to sudo, and the normal --timeout option is unavailable. Perf works when called normally outside of the Python script as well.

The information is written to the file, just not collected. How can I collect this information so it is properly collected?

`perf stat` prints its output on stderr. Redirect that instead of stdout, or do `2>&1` if you're using a shell to redirect stderr to the same FD as stdout. — Peter Cordes, Oct 06 '21 at 03:43
@PeterCordes It is outputting to a file fine, my main problem is that when I kill the perf call with a command it just says ``. Using `Ctrl + C` it outputs the information as it should. I will clarify this in the question, my apologies — , Oct 06 '21 at 04:06
Why are you piping at all, then? Is there some other output you are capturing? Or does Python not have fork/exec other than via a pipe? — Peter Cordes, Oct 06 '21 at 04:46
Anyway, are you sure the process you attached to generated any events during the interval perf was running for? If not, e.g. if it was asleep and never work up, you get `` even if perf was outputting to the terminal and killed with control-C. (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.) i.e. you should treat `` as `0`. — Peter Cordes, Oct 06 '21 at 04:47
@PeterCordes As it would seem, I may be missing a chunk of my brain. I have wasted so much time on this issue and it turns out that that is what the problem was. I modified my testing script and metrics came up. Thank you so much, I have been trying to figure out what was wrong for far too long — , Oct 06 '21 at 05:04

score 0 · Answer 1 · answered Oct 06 '21 at 03:49

0

Take a look at this answer from a previous post. Essentially, the best way to handle that would be in a "Pythonic" way, rather than ask popen to handle that. So in your case, you'd wanna do something like that:

from subprocess import PIPE, Popen

command = f"perf stat -d -p {pid_executable}"
with Popen(command, stdout=PIPE, stderr=None, shell=True) as process:
    output = process.communicate()[0].decode("utf-8")
    with open("perf_stat.txt", "w") as f:
        f.write(output)

TBH I wrote this without testing, but it should work the way it's written

answered Oct 06 '21 at 03:49

Moshe Vayner

738
1
8
23

I will look into that post, thank you. Within the function that would I still be able to get the PID of the perf_process with something like `os.environ['MODEL_PERF'] = str(os.system('echo $!'))` ? Testing your ideas now. And then later kill the call after the `ouput = process.communicate()...` line? – Oct 06 '21 at 04:13
1

@questioner1234 Yeah sure, whenever you wish to kill the process, you can simply call `process.terminate()` and that would send a `SIGTERM` (or you can also use `process.kill()` to send a `SIGKILL` if you prefer, your call ). You can read more about the `subprocess` module in the official docs, it's a pretty great module. https://docs.python.org/3/library/subprocess.html#module-subprocess – Moshe Vayner Oct 06 '21 at 18:11

score 0 · Accepted Answer · answered Oct 06 '21 at 05:16

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.

Redirect perf ouput

2 Answers2