5

I have a script that reports the cpu usage of a specific program reading values from pidstat. The script launches as:

pidstat -C ^frontend$ -h -l -p ALL 1 1

The values reported this way sometimes exceed 100% cpu usage, which it's not possible since the process is single-trheaded.

After going up and down trying to find what could be causing this behaviour, I tried to simply increase the time pidstat would collect info for, and found that surprisingly, the values tend to be much more reasonable:

pidstat -C ^frontend$ -h -l -p ALL 1 10
Linux 3.13.0-32-generic (eu-123)    09/22/2014  _x86_64_    (8 CPU)

#      Time       PID    %usr %system  %guest    %CPU   CPU  Command
 1411396853     15884   28.43   29.41    0.00   57.84     1  /srv/propulsor/frontend-01/frontend 
 1411396853     15911   33.33   32.35    0.00   65.69     2  /srv/propulsor/frontend-02/frontend 
 1411396853     15968   58.82    0.00    0.00   58.82     3  /srv/propulsor/frontend-03/frontend 

#      Time       PID    %usr %system  %guest    %CPU   CPU  Command
 1411396854     15884  141.00    4.00    0.00  145.00     1  /srv/propulsor/frontend-01/frontend 
 1411396854     15911  143.00    5.00    0.00  148.00     2  /srv/propulsor/frontend-02/frontend 
 1411396854     15968   32.00   13.00    0.00   45.00     3  /srv/propulsor/frontend-03/frontend 

#      Time       PID    %usr %system  %guest    %CPU   CPU  Command
 1411396855     15884    0.00    0.00    0.00    0.00     1  /srv/propulsor/frontend-01/frontend 
 1411396855     15911    0.00    0.00    0.00    0.00     2  /srv/propulsor/frontend-02/frontend 
 1411396855     15968   32.00   32.00    0.00   64.00     3  /srv/propulsor/frontend-03/frontend 

#      Time       PID    %usr %system  %guest    %CPU   CPU  Command
 1411396856     15884   61.00    0.00    0.00   61.00     1  /srv/propulsor/frontend-01/frontend 
 1411396856     15911   69.00    0.00    0.00   69.00     2  /srv/propulsor/frontend-02/frontend 
 1411396856     15968   33.00   31.00    0.00   64.00     3  /srv/propulsor/frontend-03/frontend 

#      Time       PID    %usr %system  %guest    %CPU   CPU  Command
 1411396857     15884   30.00    7.00    0.00   37.00     1  /srv/propulsor/frontend-01/frontend 
 1411396857     15911   34.00   20.00    0.00   54.00     2  /srv/propulsor/frontend-02/frontend 
 1411396857     15968   32.00   32.00    0.00   64.00     3  /srv/propulsor/frontend-03/frontend 

#      Time       PID    %usr %system  %guest    %CPU   CPU  Command
 1411396858     15884   31.00   32.00    0.00   63.00     1  /srv/propulsor/frontend-01/frontend 
 1411396858     15911   34.00   33.00    0.00   67.00     2  /srv/propulsor/frontend-02/frontend 
 1411396858     15968  141.00    7.00    0.00  148.00     3  /srv/propulsor/frontend-03/frontend 

[snip]

Compared to:

root@eu-123 ~ # pidstat -C ^frontend$ -h -l -p ALL 3 10
Linux 3.13.0-32-generic (eu-123)    09/22/2014  _x86_64_    (8 CPU)

#      Time       PID    %usr %system  %guest    %CPU   CPU  Command
 1411397159     15884   37.09   10.60    0.00   47.68     1  /srv/propulsor/frontend-01/frontend 
 1411397159     15911   30.46   29.80    0.00   60.26     2  /srv/propulsor/frontend-02/frontend 
 1411397159     15968   60.60   13.25    0.00   73.84     3  /srv/propulsor/frontend-03/frontend 

#      Time       PID    %usr %system  %guest    %CPU   CPU  Command
 1411397162     15884   29.33   29.33    0.00   58.67     1  /srv/propulsor/frontend-01/frontend 
 1411397162     15911   66.00    2.00    0.00   68.00     2  /srv/propulsor/frontend-02/frontend 
 1411397162     15968   41.00   15.00    0.00   56.00     3  /srv/propulsor/frontend-03/frontend 

#      Time       PID    %usr %system  %guest    %CPU   CPU  Command
 1411397165     15884   66.33    0.00    0.00   66.33     1  /srv/propulsor/frontend-01/frontend 
 1411397165     15911   30.00   19.67    0.00   49.67     2  /srv/propulsor/frontend-02/frontend 
 1411397165     15968   61.00   13.33    0.00   74.33     3  /srv/propulsor/frontend-03/frontend 

#      Time       PID    %usr %system  %guest    %CPU   CPU  Command
 1411397168     15884   30.00   23.33    0.00   53.33     1  /srv/propulsor/frontend-01/frontend 
 1411397168     15911   66.00   21.33    0.00   87.33     2  /srv/propulsor/frontend-02/frontend 
 1411397168     15968   42.00   15.67    0.00   57.67     3  /srv/propulsor/frontend-03/frontend 

#      Time       PID    %usr %system  %guest    %CPU   CPU  Command
 1411397171     15884   59.00   12.33    0.00   71.33     1  /srv/propulsor/frontend-01/frontend 
 1411397171     15911   30.00    0.67    0.00   30.67     2  /srv/propulsor/frontend-02/frontend 
 1411397171     15968   70.00   24.67    0.00   94.67     3  /srv/propulsor/frontend-03/frontend 

#      Time       PID    %usr %system  %guest    %CPU   CPU  Command
 1411397174     15884   37.67   11.00    0.00   48.67     1  /srv/propulsor/frontend-01/frontend 
 1411397174     15911   30.00   29.67    0.00   59.67     2  /srv/propulsor/frontend-02/frontend 
 1411397174     15968   33.00    4.67    0.00   37.67     3  /srv/propulsor/frontend-03/frontend 

#      Time       PID    %usr %system  %guest    %CPU   CPU  Command
 1411397177     15884   65.33   21.67    0.00   87.00     1  /srv/propulsor/frontend-01/frontend 
 1411397177     15911   65.67    2.33    0.00   68.00     2  /srv/propulsor/frontend-02/frontend 
 1411397177     15968   32.33   32.00    0.00   64.33     3  /srv/propulsor/frontend-03/frontend 

#      Time       PID    %usr %system  %guest    %CPU   CPU  Command
 1411397180     15884   29.00    0.00    0.00   29.00     1  /srv/propulsor/frontend-01/frontend 
 1411397180     15911   30.00   19.33    0.00   49.33     2  /srv/propulsor/frontend-02/frontend 
 1411397180     15968   70.00    2.33    0.00   72.33     3  /srv/propulsor/frontend-03/frontend 

[snip]

Ok, so now the read looks more reasonable, but the question for me remains, what is it causing such a difference? And how can pidstat 1 1 return values over 100%?

Bonus question: Should I be just using different tools to track cpu usage of my processes?

Thanks in advance

Edit: I kept researching the issue. Seems like the process only starts doing such a strange thing after a while (namely ~2 weeks of lifetime). In the same time we found an increased amount of connections handled by the process.

The observed behaviour is to get a couple of runs of pidstat with a flat 0% cpu usage followed by a high peak, which averaged in the magnitude of tenths stays within expected cpu usage values.

I'm starting to think it could be something like the application is doing some loop of system calls through the connection pool which after a while is big enough so that it doesn't write down its /proc/ stats making pidstat believe that the usage is 0% and therefore hitting a big >100% usage after a couple rounds on 0.

When does the process write the /proc/ data? As far as I understand, pidstat uses that info to calculate the cpu usage, or am I wrong?

I hope for someone to shed some light on this issue...

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.