[chromium-bugs] Issue 579897 in chromium: browser taking 100%

[c***@googlecode.com]

Status: Untriaged
Owner: ***@chromium.org
CC: ***@google.com, ***@google.com
Labels: Cr-OS-Kernel OS-Chrome Type-Bug M-49 Proj-Samus Pri-2
hotlist-dogfood

New issue 579897 by ***@chromium.org: browser taking 100%
https://code.google.com/p/chromium/issues/detail?id=579897

from jmeurin

https://feedback.corp.google.com/#/Report/6705192899

Description:
Browser is still taking 100%

UI language: en-US

Product Specific Data (whitelisted):
CHROME VERSION: 49.0.2618.9 dev
CHROMEOS_AUSERVER: https://tools.google.com/service/update2
CHROMEOS_RELEASE_BOARD: samus-signed-mpkeys
CHROMEOS_RELEASE_DESCRIPTION: 7821.2.0 (Official Build) dev-channel samus
CHROMEOS_RELEASE_TRACK: dev-channel
CHROMEOS_RELEASE_VERSION: 7821.2.0
ENTERPRISE_ENROLLED: Managed
--
You received this message because this project is configured to send all
issue notifications to this address.
You may adjust your notification preferences at:
https://code.google.com/hosting/settings

[c***@googlecode.com]

Updates:
Owner: ***@chromium.org
Cc: ***@chromium.org

Comment #1 on issue 579897 by ***@chromium.org: browser taking 100%
https://code.google.com/p/chromium/issues/detail?id=579897

To abodenha based on the dogfood thread.
--
You received this message because this project is configured to send all
issue notifications to this address.
You may adjust your notification preferences at:
https://code.google.com/hosting/settings

[c***@googlecode.com]

Updates:
Cc: ***@chromium.org ***@chromium.org ***@chromium.org
***@chromium.org ***@chromium.org

Comment #3 on issue 579897 by ***@chromium.org: browser taking 100%
https://code.google.com/p/chromium/issues/detail?id=579897

I noticed there are a lot of extensions running, and from the system logs,
the following events are logged almost continuously, repeatedly the entire
time:

[32200:32222:0119/155444:ERROR:message_pipe_dispatcher.cc(976)]
MessagePipeDispatcher read error (connection broken)
[32200:32218:0119/155445:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid <pid>: Permission denied

That could be related somehow?

It seems that adjusting the renderer OOM score happens as a result of the
following:
- Every 10 seconds, when TabManager::UpdateTimerCallback() is called back
by the |update_timer_|
(https://code.google.com/p/chromium/codesearch#chromium/src/chrome/browser/memory/tab_manager.cc&q=TabManager::UpdateTimerCallback&sq=package:chromium&type=cs&l=481).

- Sometimes when tab focus is changed?
(https://code.google.com/p/chromium/codesearch#chromium/src/chrome/browser/memory/tab_manager_delegate_chromeos.cc&q=TabManagerDelegate::Observe&sq=package:chromium&type=cs&l=122).

Is that a case where the browser process doesn't have enough permissions to
modify "/proc/<pid>/oom_score_adj"?

Adding owners of the code mentioned above.
--
You received this message because this project is configured to send all
issue notifications to this address.
You may adjust your notification preferences at:
https://code.google.com/hosting/settings

[c***@googlecode.com]

Comment #4 on issue 579897 by ***@chromium.org: browser taking 100%
https://code.google.com/p/chromium/issues/detail?id=579897

fwiw, I don't think the OOM score message is likely to be related to the
100% CPU issue, but we definitely shouldn't be seeing that failure.

Does chrome://sandbox/ say that the namespace sandbox is enabled?

Also, is it possible to get the output of ls -l /proc/<pid> for a renderer
on the device?
--
You received this message because this project is configured to send all
issue notifications to this address.
You may adjust your notification preferences at:
https://code.google.com/hosting/settings

[c***@googlecode.com]

Comment #5 on issue 579897 by ***@chromium.org: browser taking 100%
https://code.google.com/p/chromium/issues/detail?id=579897

Yeah, the message itself might not be expensive, but could the function
base::AdjustOOMScore() be, especially if it is executed repeatedly?

***@google.com: Can you provide rickyz with what he requested in #4?
--
You received this message because this project is configured to send all
issue notifications to this address.
You may adjust your notification preferences at:
https://code.google.com/hosting/settings

[c***@googlecode.com]

Comment #6 on issue 579897 by ***@google.com: browser taking 100%
https://code.google.com/p/chromium/issues/detail?id=579897

It was too painful so I rebooted and it's been behaving for the past 10
minutes. I currently have:
Sandbox Status
SUID Sandbox No
Namespace Sandbox Yes
PID namespaces Yes
Network namespaces Yes
Seccomp-BPF sandbox Yes
Seccomp-BPF sandbox supports TSYNC Yes
Yama LSM enforcing Yes

You are adequately sandboxed.


I'm not sure how I can run the ls /proc command?

Jean-Marc
--
You received this message because this project is configured to send all
issue notifications to this address.
You may adjust your notification preferences at:
https://code.google.com/hosting/settings

[c***@googlecode.com]

Comment #7 on issue 579897 by ***@chromium.org: browser taking 100%
https://code.google.com/p/chromium/issues/detail?id=579897

Is the chromebook in developer mode by any chance (I'm guessing it's not
based on the "managed" string)? If not, it won't be easy to get a shell on
the device, but I can probably try to find one to test.

Regarding base::AdjustOOMScore, that's what I meant - base::AdjustOOMScore
should not be particularly expensive, and if I'm reading the code
correctly, there should only be an adjustment on a tab switch, which is why
I don't believe it is likely to be related to the 100% CPU usage.
--
You received this message because this project is configured to send all
issue notifications to this address.
You may adjust your notification preferences at:
https://code.google.com/hosting/settings

[c***@googlecode.com]

Comment #8 on issue 579897 by ***@chromium.org: browser taking 100%
https://code.google.com/p/chromium/issues/detail?id=579897

Judging from the system_logs.txt (attached with the feedback report), it
seems that base::AdjustOOMScore() is called a lot, sometimes multiple times
per second, once for each renderer! I could be wrong though.

A sample of the logs are pasted here:

[32200:32220:0119/110307:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 578: Permission denied
[32200:32220:0119/110307:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 579: Permission denied
[32200:32220:0119/110307:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 581: Permission denied
[32200:32220:0119/110307:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 590: Permission denied
[32200:32220:0119/110307:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 594: Permission denied
[32200:32220:0119/110307:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 598: Permission denied
[32200:32220:0119/110307:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 603: Permission denied
[32200:32220:0119/110307:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 618: Permission denied
[32200:32200:0119/110307:ERROR:child_process_task_provider.cc(148)]
NOTREACHED() hit.
[32200:32200:0119/110307:WARNING:extension_error_reporter.cc(79)] Extension
error: Could not add application because it conflicts with "Web Store".
[32200:32220:0119/110307:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 631: Permission denied
[32200:32222:0119/110307:ERROR:message_pipe_dispatcher.cc(976)]
MessagePipeDispatcher read error (connection broken)
[32200:32222:0119/110307:ERROR:message_pipe_dispatcher.cc(976)]
MessagePipeDispatcher read error (connection broken)
[32200:32222:0119/110307:ERROR:message_pipe_dispatcher.cc(976)]
MessagePipeDispatcher read error (connection broken)
[32200:32200:0119/110307:ERROR:child_process_task_provider.cc(148)]
NOTREACHED() hit.
[32200:32220:0119/110308:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 639: Permission denied
[32200:32222:0119/110308:ERROR:message_pipe_dispatcher.cc(976)]
MessagePipeDispatcher read error (connection broken)
[32200:32222:0119/110308:ERROR:message_pipe_dispatcher.cc(976)]
MessagePipeDispatcher read error (connection broken)
[32200:32222:0119/110308:ERROR:message_pipe_dispatcher.cc(976)]
MessagePipeDispatcher read error (connection broken)
[32200:32220:0119/110308:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 652: Permission denied
[32200:32220:0119/110308:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 663: Permission denied
[32200:32218:0119/110309:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 652: Permission denied
[32200:32220:0119/110309:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 694: Permission denied
[32200:32218:0119/110310:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 32408: Permission denied
[32200:32218:0119/110310:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 32509: Permission denied
[32200:32218:0119/110310:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 32264: Permission denied
[32200:32218:0119/110310:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 694: Permission denied
[32200:32218:0119/110310:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 32546: Permission denied
[32200:32218:0119/110310:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 32609: Permission denied
[32200:32218:0119/110310:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 32624: Permission denied
[32200:32218:0119/110310:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 32732: Permission denied
[32200:32218:0119/110310:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 418: Permission denied
[32200:32218:0119/110310:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 430: Permission denied
[32200:32218:0119/110310:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 436: Permission denied
[32200:32218:0119/110310:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 448: Permission denied
[32200:32218:0119/110310:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 481: Permission denied
[32200:32215:0119/110310:ERROR:chrome_rlz_tracker_delegate.cc(119)] Not
implemented reached in virtual bool
ChromeRLZTrackerDelegate::GetLanguage(base::string16*)
[32200:32200:0119/110310:ERROR:extension_pref_value_map.cc(72)]
NOTREACHED() hit.
[32200:32218:0119/110311:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 32324: Permission denied
[32200:32222:0119/110311:WARNING:message_in_transit_queue.cc(17)]
Destroying nonempty message queue
[32200:32220:0119/110311:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 720: Permission denied
[32200:728:0119/110311:WARNING:audio_sync_reader.cc(112)]
AudioSyncReader::Read timed out, audio glitch count=1
[32200:32218:0119/110312:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 0: No such file or directory
[32200:32220:0119/110313:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 751: Permission denied
[32200:32220:0119/110314:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 797: Permission denied
[32200:32220:0119/110316:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 833: Permission denied
[32200:32222:0119/110316:ERROR:message_pipe_dispatcher.cc(976)]
MessagePipeDispatcher read error (connection broken)
[32200:32222:0119/110316:ERROR:message_pipe_dispatcher.cc(976)]
MessagePipeDispatcher read error (connection broken)
[32200:32220:0119/110316:ERROR:zygote_host_impl_linux.cc(512)] Failed to
adjust OOM score of renderer with pid 840: Permission denied
[32200:32222:0119/110316:ERROR:message_pipe_dispatcher.cc(976)]
MessagePipeDispatcher read error (connection broken)
[32200:32222:0119/110316:ERROR:message_pipe_dispatcher.cc(976)]
MessagePipeDispatcher read error (connection broken)
[32200:32222:0119/110316:ERROR:message_pipe_dispatcher.cc(976)]
MessagePipeDispatcher read error (connection broken)
[32200:32222:0119/110316:ERROR:message_pipe_dispatcher.cc(976)]
MessagePipeDispatcher read error (connection broken)
--
You received this message because this project is configured to send all
issue notifications to this address.
You may adjust your notification preferences at:
https://code.google.com/hosting/settings

[c***@googlecode.com]

Comment #9 on issue 579897 by ***@chromium.org: browser taking 100%
https://code.google.com/p/chromium/issues/detail?id=579897

Ah yes, it looks like there is another task which updates the OOM score for
all renderers every 10s or so
(https://code.google.com/p/chromium/codesearch#chromium/src/chrome/browser/memory/tab_manager_delegate_chromeos.cc&sq=package:chromium&l=203),
so if permissions on the file that it writes are too tight, it makes sense
that it would log failures for all renderers in rapid succession when that
runs. It is surprising that they do not all complete in the same second or
two, though that could be a symptom of the high CPU usage.

Another reason that I don't think these are related to the CPU issue: Apart
from printing a log message, the failure of those calls should not affect
the logic of the program - the value being changed should only come into
effect when the OOM killer runs and needs to select a process to kill. If
not for the bug that was causing these writes to fail, we would expect the
same calls to be taking place.

For debugging the 100% CPU usage - the next time it happens, I'd suggest
forcibly crashing the browser by going to:

chrome:///inducebrowsercrashforrealz

Then grabbing the crash id from chrome:///crashes when it restarts - then
we could inspect the thread stack traces to see if there was a thread stuck
in a look or something.
--
You received this message because this project is configured to send all
issue notifications to this address.
You may adjust your notification preferences at:
https://code.google.com/hosting/settings

[c***@googlecode.com]

Comment #10 on issue 579897 by ***@google.com: browser taking 100%
https://code.google.com/p/chromium/issues/detail?id=579897

It just happened and I tried the crash for real URL and it crashed but
there's no record of it in the crashes..
--
You received this message because this project is configured to send all
issue notifications to this address.
You may adjust your notification preferences at:
https://code.google.com/hosting/settings

[c***@googlecode.com]

Comment #13 on issue 579897 by ***@chromium.org: browser taking 100%
https://code.google.com/p/chromium/issues/detail?id=579897

Thanks for grabbing the dump - just to confirm, this is the browser process
using 100% CPU, right?

I'm not sure whether the forced crash does anything to disrupt the behavior
of whatever thread is taking up CPU, but assuming it doesn't, the only
thread which doesn't look blocked on a system call is thread 11, which is
inside of net::HttpRequestHeaders::~HttpRequestHeaders. I wonder if that
thread's stack trace could be a clue about the culprit.

Getting more crash dumps like might help us find commonalities between
dumps with 100% CPU, so please keep them coming if you encounter this again!
--
You received this message because this project is configured to send all
issue notifications to this address.
You may adjust your notification preferences at:
https://code.google.com/hosting/settings

[c***@googlecode.com]

Comment #14 on issue 579897 by ***@chromium.org: browser taking 100%
https://code.google.com/p/chromium/issues/detail?id=579897

Yes, this is the browser process. I'll send more dumps as I find them.
--
You received this message because this project is configured to send all
issue notifications to this address.
You may adjust your notification preferences at:
https://code.google.com/hosting/settings

[c***@googlecode.com]

Updates:
Status: Duplicate
Mergedinto: 574859

Comment #16 on issue 579897 by ***@chromium.org: browser taking 100%
https://code.google.com/p/chromium/issues/detail?id=579897

Let's track this issue by a single bug.
--
You received this message because this project is configured to send all
issue notifications to this address.
You may adjust your notification preferences at:
https://code.google.com/hosting/settings

[c***@googlecode.com]

Comment #17 on issue 579897 by ***@chromium.org: browser taking 100%
https://code.google.com/p/chromium/issues/detail?id=579897

574859 is fixed, but ***@chromium.org still reports 100% cpu usage. I'm
trying to check if 574859 is actually related to 579897. There is a
probability that we have a different cause for this problem.
--
You received this message because this project is configured to send all
issue notifications to this address.
You may adjust your notification preferences at:
https://code.google.com/hosting/settings

[c***@googlecode.com]

Comment #18 on issue 579897 by ***@chromium.org: browser taking 100%
https://code.google.com/p/chromium/issues/detail?id=579897

574859 is fixed, but ***@chromium.org still reports 100% cpu usage. I'm
trying to check if 574859 is actually related to 579897. There is a
probability that we have a different cause for this problem.
--
You received this message because this project is configured to send all
issue notifications to this address.
You may adjust your notification preferences at:
https://code.google.com/hosting/settings