You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@aurora.apache.org by "Reza Motamedi (JIRA)" <ji...@apache.org> on 2017/07/19 20:57:00 UTC
[jira] [Comment Edited] (AURORA-1939) Thermos landing (host) page
reports incorrect CPU rates when it is busy
[ https://issues.apache.org/jira/browse/AURORA-1939?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16093763#comment-16093763 ]
Reza Motamedi edited comment on AURORA-1939 at 7/19/17 8:56 PM:
----------------------------------------------------------------
I added more debug logs to trace what is kept in the process tree:
{noformat}
D0719 20:23:05.758181 24474 process_collector_psutil.py:105] Calculated rate for pid=62328 and children: 0.000365496747142 (old: 885.570000, new: 885.670000)
{62328: 1500007014.22, 866: 1500007038.32} -> {62328: 1500007014.22, 866: 1500007038.32}
[{62328: ProcessSample(rate=0.0, user=0.0, system=0.02, rss=2609152, vms=11919360, nice=0, status='sleeping', threads=1), 866: ProcessSample(rate=0.0, user=315.39, system=570.16, rss=36704256, vms=1601019904, nice=0, status='sleeping', threads=20)}]
[{62328: ProcessSample(rate=0.0, user=0.0, system=0.02, rss=2609152, vms=11919360, nice=0, status='sleeping', threads=1), 866: ProcessSample(rate=0.0, user=314.96, system=570.69, rss=36134912, vms=1601019904, nice=0, status='sleeping', threads=20)}]
D0719 20:27:44.454570 24474 process_collector_psutil.py:105] Calculated rate for pid=62328 and children: 2.10562464635 (old: 885.670000, new: 1472.500000)
{62328: 1500007014.22, 866: 1500007038.32} -> {62328: 1500007014.22, 866: 1500007038.32}
[{62328: ProcessSample(rate=0.0, user=0.0, system=0.02, rss=2609152, vms=11919360, nice=0, status='sleeping', threads=1), 866: ProcessSample(rate=0.0, user=314.96, system=570.69, rss=36134912, vms=1601019904, nice=0, status='sleeping', threads=20)}]
[{62328: ProcessSample(rate=0.0, user=0.0, system=0.02, rss=2609152, vms=11919360, nice=0, status='sleeping', threads=1), 866: ProcessSample(rate=0.0, user=520.93, system=951.55, rss=35430400, vms=1600204800, nice=0, status='sleeping', threads=20)}]
D0719 20:32:29.451004 24474 process_collector_psutil.py:105] Calculated rate for pid=62328 and children: 0.00294740555899 (old: 1472.500000, new: 1473.340000)
{62328: 1500007014.22, 866: 1500007038.32} -> {62328: 1500007014.22, 866: 1500007038.32}
[{62328: ProcessSample(rate=0.0, user=0.0, system=0.02, rss=2609152, vms=11919360, nice=0, status='sleeping', threads=1), 866: ProcessSample(rate=0.0, user=520.93, system=951.55, rss=35430400, vms=1600204800, nice=0, status='sleeping', threads=20)}]
[{62328: ProcessSample(rate=0.0, user=0.0, system=0.02, rss=2609152, vms=11919360, nice=0, status='sleeping', threads=1), 866: ProcessSample(rate=0.0, user=521.23, system=952.09, rss=35430400, vms=1600204800, nice=0, status='sleeping', threads=20)}]
D0719 20:37:10.152525 24474 process_collector_psutil.py:105] Calculated rate for pid=62328 and children: 0.00299250250927 (old: 1473.340000, new: 1474.180000)
{62328: 1500007014.22, 866: 1500007038.32} -> {62328: 1500007014.22, 866: 1500007038.32}
[{62328: ProcessSample(rate=0.0, user=0.0, system=0.02, rss=2609152, vms=11919360, nice=0, status='sleeping', threads=1), 866: ProcessSample(rate=0.0, user=521.23, system=952.09, rss=35430400, vms=1600204800, nice=0, status='sleeping', threads=20)}]
[{62328: ProcessSample(rate=0.0, user=0.0, system=0.02, rss=2609152, vms=11919360, nice=0, status='sleeping', threads=1), 866: ProcessSample(rate=0.0, user=521.55, system=952.61, rss=35430400, vms=1600204800, nice=0, status='sleeping', threads=20)}]
D0719 20:42:58.449567 24474 process_collector_psutil.py:105] Calculated rate for pid=62328 and children: -1.64913818086 (old: 1474.180000, new: 899.790000)
{62328: 1500007014.22, 866: 1500007038.32} -> {62328: 1500007014.22, 866: 1500007038.32}
[{62328: ProcessSample(rate=0.0, user=0.0, system=0.02, rss=2609152, vms=11919360, nice=0, status='sleeping', threads=1), 866: ProcessSample(rate=0.0, user=521.55, system=952.61, rss=35430400, vms=1600204800, nice=0, status='sleeping', threads=20)}]
[{62328: ProcessSample(rate=0.0, user=0.0, system=0.02, rss=2732032, vms=11919360, nice=0, status='sleeping', threads=1), 866: ProcessSample(rate=0.0, user=322.65, system=577.12, rss=35430400, vms=1600204800, nice=0, status='sleeping', threads=20)}]
{noformat}
Note:
{noformat}
{62328: 1500007014.22, 866: 1500007038.32} -> {62328: 1500007014.22, 866: 1500007038.32}
{noformat}
means what processes where in the old and new sample, as in old -> new. The map also includes the pid creation time. Therefor, I can role out the problem with pid reuse.
The line after that is the ProcessSamples in the old pstree, kept in the object as "pid => ProcessSample", and the line after is the new sample.
was (Author: rezam):
I added more debug logs to trace what is kept in the process tree:
{noformat}
D0719 20:23:05.758181 24474 process_collector_psutil.py:105] Calculated rate for pid=62328 and children: 0.000365496747142 (old: 885.570000, new: 885.670000)
{62328: 1500007014.22, 866: 1500007038.32} -> {62328: 1500007014.22, 866: 1500007038.32}
[{62328: ProcessSample(rate=0.0, user=0.0, system=0.02, rss=2609152, vms=11919360, nice=0, status='sleeping', threads=1), 866: ProcessSample(rate=0.0, user=315.39, system=570.16, rss=36704256, vms=1601019904, nice=0, status='sleeping', threads=20)}]
[{62328: ProcessSample(rate=0.0, user=0.0, system=0.02, rss=2609152, vms=11919360, nice=0, status='sleeping', threads=1), 866: ProcessSample(rate=0.0, user=314.96, system=570.69, rss=36134912, vms=1601019904, nice=0, status='sleeping', threads=20)}]
D0719 20:27:44.454570 24474 process_collector_psutil.py:105] Calculated rate for pid=62328 and children: 2.10562464635 (old: 885.670000, new: 1472.500000)
{62328: 1500007014.22, 866: 1500007038.32} -> {62328: 1500007014.22, 866: 1500007038.32}
[{62328: ProcessSample(rate=0.0, user=0.0, system=0.02, rss=2609152, vms=11919360, nice=0, status='sleeping', threads=1), 866: ProcessSample(rate=0.0, user=314.96, system=570.69, rss=36134912, vms=1601019904, nice=0, status='sleeping', threads=20)}]
[{62328: ProcessSample(rate=0.0, user=0.0, system=0.02, rss=2609152, vms=11919360, nice=0, status='sleeping', threads=1), 866: ProcessSample(rate=0.0, user=520.93, system=951.55, rss=35430400, vms=1600204800, nice=0, status='sleeping', threads=20)}]
D0719 20:32:29.451004 24474 process_collector_psutil.py:105] Calculated rate for pid=62328 and children: 0.00294740555899 (old: 1472.500000, new: 1473.340000)
{62328: 1500007014.22, 866: 1500007038.32} -> {62328: 1500007014.22, 866: 1500007038.32}
[{62328: ProcessSample(rate=0.0, user=0.0, system=0.02, rss=2609152, vms=11919360, nice=0, status='sleeping', threads=1), 866: ProcessSample(rate=0.0, user=520.93, system=951.55, rss=35430400, vms=1600204800, nice=0, status='sleeping', threads=20)}]
[{62328: ProcessSample(rate=0.0, user=0.0, system=0.02, rss=2609152, vms=11919360, nice=0, status='sleeping', threads=1), 866: ProcessSample(rate=0.0, user=521.23, system=952.09, rss=35430400, vms=1600204800, nice=0, status='sleeping', threads=20)}]
D0719 20:37:10.152525 24474 process_collector_psutil.py:105] Calculated rate for pid=62328 and children: 0.00299250250927 (old: 1473.340000, new: 1474.180000)
{62328: 1500007014.22, 866: 1500007038.32} -> {62328: 1500007014.22, 866: 1500007038.32}
[{62328: ProcessSample(rate=0.0, user=0.0, system=0.02, rss=2609152, vms=11919360, nice=0, status='sleeping', threads=1), 866: ProcessSample(rate=0.0, user=521.23, system=952.09, rss=35430400, vms=1600204800, nice=0, status='sleeping', threads=20)}]
[{62328: ProcessSample(rate=0.0, user=0.0, system=0.02, rss=2609152, vms=11919360, nice=0, status='sleeping', threads=1), 866: ProcessSample(rate=0.0, user=521.55, system=952.61, rss=35430400, vms=1600204800, nice=0, status='sleeping', threads=20)}]
D0719 20:42:58.449567 24474 process_collector_psutil.py:105] Calculated rate for pid=62328 and children: -1.64913818086 (old: 1474.180000, new: 899.790000)
{62328: 1500007014.22, 866: 1500007038.32} -> {62328: 1500007014.22, 866: 1500007038.32}
[{62328: ProcessSample(rate=0.0, user=0.0, system=0.02, rss=2609152, vms=11919360, nice=0, status='sleeping', threads=1), 866: ProcessSample(rate=0.0, user=521.55, system=952.61, rss=35430400, vms=1600204800, nice=0, status='sleeping', threads=20)}]
[{62328: ProcessSample(rate=0.0, user=0.0, system=0.02, rss=2732032, vms=11919360, nice=0, status='sleeping', threads=1), 866: ProcessSample(rate=0.0, user=322.65, system=577.12, rss=35430400, vms=1600204800, nice=0, status='sleeping', threads=20)}]
{noformat}
Note: {62328: 1500007014.22, 866: 1500007038.32} -> {62328: 1500007014.22, 866: 1500007038.32} what processes where in the old and new sample, as in old -> new. The line after that is the ProcessSamples in the old pstree, kept in the object as "pid => ProcessSample", and the line after is the new sample.
> Thermos landing (host) page reports incorrect CPU rates when it is busy
> -----------------------------------------------------------------------
>
> Key: AURORA-1939
> URL: https://issues.apache.org/jira/browse/AURORA-1939
> Project: Aurora
> Issue Type: Bug
> Reporter: Reza Motamedi
> Priority: Minor
>
> Thermos Observer uses `psutil` to monitor resource consumption of Thermos Processes. On a busy machine, I have noticed negative CPU values when visiting the Thermos landing page.
> In my test I reproduced this by starting many processes that constantly create short lived children. This indicates that in time between `process_collector_psutil` looks up the Process children and the time it calculates the CPU time the pid of the child is actually reused by another much younger process, which leads to negative CPU times.
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)