Log app and tab discards.

Log app and tab discards.

On critical memory pressure, we already log entries at least for every
tab and extension and the corresponding memory usage. However, there's
no logging for the action that was taken in response.

This should help us understand discard behavior in feedback reports from
users.

BUG=709253
TEST=build

Review-Url: https://codereview.chromium.org/2811433002
Cr-Commit-Position: refs/heads/master@{#464018}
Committed: https://chromium.googlesource.com/chromium/src/+/53cb7fcf9db050cac655e47ff85d02daac7dbb22

[teravest, 2017-04-08 00:53:22]

The CQ bit was checked by teravest@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2017-04-08 00:53:57]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2017-04-08 00:56:45]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2017-04-08 00:56:46]

Dry run: Try jobs failed on following builders:
  ios-device on master.tryserver.chromium.mac (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.mac/builders/ios-device/builds...)
  ios-device-xcode-clang on master.tryserver.chromium.mac (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.mac/builders/ios-device-xcode-...)
  ios-simulator-xcode-clang on master.tryserver.chromium.mac (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.mac/builders/ios-simulator-xco...)
  mac_chromium_rel_ng on master.tryserver.chromium.mac (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.mac/builders/mac_chromium_rel_...)

[teravest, 2017-04-08 01:03:15]

The CQ bit was checked by teravest@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2017-04-08 01:03:37]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2017-04-08 01:12:26]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2017-04-08 01:12:27]

Dry run: Try jobs failed on following builders:
  ios-device on master.tryserver.chromium.mac (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.mac/builders/ios-device/builds...)

[teravest, 2017-04-08 01:15:15]

The CQ bit was checked by teravest@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2017-04-08 01:15:42]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[teravest, 2017-04-08 01:59:21]

teravest@chromium.org changed reviewers:
+ derat@chromium.org

[commit-bot: I haz the power, 2017-04-08 02:20:37]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2017-04-08 02:20:38]

Dry run: Try jobs failed on following builders:
  linux_chromium_chromeos_ozone_rel_ng on master.tryserver.chromium.linux
(JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.linux/builders/linux_chromium_...)

[Daniel Erat, 2017-04-08 15:06:38]

change itself looks fine to me, but it may be causing some test crashes:

[ RUN      ] TabManagerDelegateTest.KillMultipleProcesses
[28910:28910:0407/192034.624992:8991527233:FATAL:sequenced_task_runner_handle.cc(54)]
Check failed: pool. 
#0 0x000004b8b997 base::debug::StackTrace::StackTrace()
#1 0x000004ba2f6a logging::LogMessage::~LogMessage()
#2 0x000004bf568b base::SequencedTaskRunnerHandle::Get()
#3 0x000004bf939c base::SequencedWorkerPool::SequencedWorkerPool()
#4 0x000002ac008c base::LazyInstance<>::Get()
#5 0x000002ac1958 content::BrowserThread::CurrentlyOn()
#6 0x000005132603 memory::TabManagerDelegate::LowMemoryKillImpl()
#7 0x000000e0c6da
memory::TabManagerDelegateTest_KillMultipleProcesses_Test::TestBody()
#8 0x0000048fd676 testing::Test::Run()
#9 0x0000048fe120 testing::TestInfo::Run()
#10 0x0000048fe647 testing::TestCase::Run()
#11 0x000004905687 testing::internal::UnitTestImpl::RunAllTests()
#12 0x000004905307 testing::UnitTest::Run()
#13 0x00000413d4d1 base::TestSuite::Run()
#14 0x00000413ece1 base::(anonymous namespace)::LaunchUnitTestsInternal()
#15 0x00000413eb64 base::LaunchUnitTests()
#16 0x000004137197 main
#17 0x7ff4b7f81f45 __libc_start_main
#18 0x0000006c06cd <unknown>

[8656/8661] TabManagerDelegateTest.KillMultipleProcesses (CRASHED)

https://codereview.chromium.org/2811433002/diff/40001/chrome/browser/memory/t...
File chrome/browser/memory/tab_manager_delegate_chromeos.cc (right):

https://codereview.chromium.org/2811433002/diff/40001/chrome/browser/memory/t...
chrome/browser/memory/tab_manager_delegate_chromeos.cc:614: MEMORY_LOG(ERROR) <<
"Killed " << *it;
how about also including estimated_memory_freed_kb here and in the next message?

[teravest, 2017-04-10 15:39:01]

The CQ bit was checked by teravest@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2017-04-10 15:39:20]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[teravest, 2017-04-10 16:19:52]

The CQ bit was checked by teravest@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2017-04-10 16:20:11]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2017-04-10 17:18:12]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2017-04-10 17:18:13]

Dry run: This issue passed the CQ dry run.

[teravest, 2017-04-10 17:25:59]

On 2017/04/08 15:06:38, Daniel Erat wrote:
> change itself looks fine to me, but it may be causing some test crashes:
> 
> [ RUN      ] TabManagerDelegateTest.KillMultipleProcesses
>
[28910:28910:0407/192034.624992:8991527233:FATAL:sequenced_task_runner_handle.cc(54)]
> Check failed: pool. 
> #0 0x000004b8b997 base::debug::StackTrace::StackTrace()
> #1 0x000004ba2f6a logging::LogMessage::~LogMessage()
> #2 0x000004bf568b base::SequencedTaskRunnerHandle::Get()
> #3 0x000004bf939c base::SequencedWorkerPool::SequencedWorkerPool()
> #4 0x000002ac008c base::LazyInstance<>::Get()
> #5 0x000002ac1958 content::BrowserThread::CurrentlyOn()
> #6 0x000005132603 memory::TabManagerDelegate::LowMemoryKillImpl()
> #7 0x000000e0c6da
> memory::TabManagerDelegateTest_KillMultipleProcesses_Test::TestBody()
> #8 0x0000048fd676 testing::Test::Run()
> #9 0x0000048fe120 testing::TestInfo::Run()
> #10 0x0000048fe647 testing::TestCase::Run()
> #11 0x000004905687 testing::internal::UnitTestImpl::RunAllTests()
> #12 0x000004905307 testing::UnitTest::Run()
> #13 0x00000413d4d1 base::TestSuite::Run()
> #14 0x00000413ece1 base::(anonymous namespace)::LaunchUnitTestsInternal()
> #15 0x00000413eb64 base::LaunchUnitTests()
> #16 0x000004137197 main
> #17 0x7ff4b7f81f45 __libc_start_main
> #18 0x0000006c06cd <unknown>
> 
> [8656/8661] TabManagerDelegateTest.KillMultipleProcesses (CRASHED)

Ah, yep, fixed.

> 
>
https://codereview.chromium.org/2811433002/diff/40001/chrome/browser/memory/t...
> File chrome/browser/memory/tab_manager_delegate_chromeos.cc (right):
> 
>
https://codereview.chromium.org/2811433002/diff/40001/chrome/browser/memory/t...
> chrome/browser/memory/tab_manager_delegate_chromeos.cc:614: MEMORY_LOG(ERROR)
<<
> "Killed " << *it;
> how about also including estimated_memory_freed_kb here and in the next
message?

Done.

[teravest, 2017-04-10 17:26:10]

The CQ bit was checked by teravest@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2017-04-10 17:26:43]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[Daniel Erat, 2017-04-10 17:39:49]

lgtm

https://codereview.chromium.org/2811433002/diff/100001/chrome/browser/memory/...
File chrome/browser/memory/tab_manager_delegate_chromeos.cc (right):

https://codereview.chromium.org/2811433002/diff/100001/chrome/browser/memory/...
chrome/browser/memory/tab_manager_delegate_chromeos.cc:615: <<
estimated_memory_freed_kb << " kB freed";
nit: "KB" rather than "kB" here and below? i think that this is units of 1024
bytes rather than 1000 bytes, per base/process/process_metrics_linux.cc. i'm
just going by https://en.wikipedia.org/wiki/Kilobyte, though, so feel free to
ignore this :-P

[teravest, 2017-04-10 17:52:02]

teravest@chromium.org changed reviewers:
+ chrisha@chromium.org, stevenjb@chromium.org

[teravest, 2017-04-10 17:52:03]

https://codereview.chromium.org/2811433002/diff/40001/chrome/browser/memory/t...
File chrome/browser/memory/tab_manager_delegate_chromeos.cc (right):

https://codereview.chromium.org/2811433002/diff/40001/chrome/browser/memory/t...
chrome/browser/memory/tab_manager_delegate_chromeos.cc:614: MEMORY_LOG(ERROR) <<
"Killed " << *it;
On 2017/04/08 15:06:37, Daniel Erat wrote:
> how about also including estimated_memory_freed_kb here and in the next
message?

Done.

https://codereview.chromium.org/2811433002/diff/100001/chrome/browser/memory/...
File chrome/browser/memory/tab_manager_delegate_chromeos.cc (right):

https://codereview.chromium.org/2811433002/diff/100001/chrome/browser/memory/...
chrome/browser/memory/tab_manager_delegate_chromeos.cc:615: <<
estimated_memory_freed_kb << " kB freed";
On 2017/04/10 17:39:49, Daniel Erat wrote:
> nit: "KB" rather than "kB" here and below? i think that this is units of 1024
> bytes rather than 1000 bytes, per base/process/process_metrics_linux.cc. i'm
> just going by https://en.wikipedia.org/wiki/Kilobyte, though, so feel free to
> ignore this :-P

Done.

[Daniel Erat, 2017-04-10 18:05:19]

thanks, still lgtm

[teravest, 2017-04-11 15:50:46]

+stevenjb for components/device_event_log OWNERS
+chrisha for chrome/browser/memory OWNERS

[stevenjb, 2017-04-11 17:12:53]

https://codereview.chromium.org/2811433002/diff/120001/chrome/browser/memory/...
File chrome/browser/memory/tab_manager_delegate_chromeos.cc (right):

https://codereview.chromium.org/2811433002/diff/120001/chrome/browser/memory/...
chrome/browser/memory/tab_manager_delegate_chromeos.cc:637: MEMORY_LOG(ERROR) <<
"No candidate killed.";
If we are logging this as an ERROR (which will go to the chrome log also), we
should be more informativie, e.g. "Low memory: Unable to kill any candidates.
Attempting to free: " << target_memory_to_free_kb;

[chrisha, 2017-04-11 18:24:26]

rubber stamp lgtm

[teravest, 2017-04-11 18:31:05]

https://codereview.chromium.org/2811433002/diff/120001/chrome/browser/memory/...
File chrome/browser/memory/tab_manager_delegate_chromeos.cc (right):

https://codereview.chromium.org/2811433002/diff/120001/chrome/browser/memory/...
chrome/browser/memory/tab_manager_delegate_chromeos.cc:637: MEMORY_LOG(ERROR) <<
"No candidate killed.";
On 2017/04/11 17:12:53, stevenjb wrote:
> If we are logging this as an ERROR (which will go to the chrome log also), we
> should be more informativie, e.g. "Low memory: Unable to kill any candidates.
> Attempting to free: " << target_memory_to_free_kb;

Sounds good, done.

[semenzato, 2017-04-11 18:39:23]

On 2017/04/11 18:31:05, teravest wrote:
>
https://codereview.chromium.org/2811433002/diff/120001/chrome/browser/memory/...
> File chrome/browser/memory/tab_manager_delegate_chromeos.cc (right):
> 
>
https://codereview.chromium.org/2811433002/diff/120001/chrome/browser/memory/...
> chrome/browser/memory/tab_manager_delegate_chromeos.cc:637: MEMORY_LOG(ERROR)
<<
> "No candidate killed.";
> On 2017/04/11 17:12:53, stevenjb wrote:
> > If we are logging this as an ERROR (which will go to the chrome log also),
we
> > should be more informativie, e.g. "Low memory: Unable to kill any
candidates.
> > Attempting to free: " << target_memory_to_free_kb;
> 
> Sounds good, done.

I have a small inline comment if I am still in time.

[semenzato, 2017-04-11 18:39:39]

semenzato@google.com changed reviewers:
+ semenzato@google.com

[semenzato, 2017-04-11 18:39:40]

https://codereview.chromium.org/2811433002/diff/140001/chrome/browser/memory/...
File chrome/browser/memory/tab_manager_delegate_chromeos.cc (right):

https://codereview.chromium.org/2811433002/diff/140001/chrome/browser/memory/...
chrome/browser/memory/tab_manager_delegate_chromeos.cc:628: MEMORY_LOG(ERROR) <<
"Killed " << *it << ", estimated "
Is the log message identical in these two cases?  It might not hurt to mention
"app" or "tab".

[teravest, 2017-04-11 18:43:32]

On 2017/04/11 18:39:40, semenzato wrote:
>
https://codereview.chromium.org/2811433002/diff/140001/chrome/browser/memory/...
> File chrome/browser/memory/tab_manager_delegate_chromeos.cc (right):
> 
>
https://codereview.chromium.org/2811433002/diff/140001/chrome/browser/memory/...
> chrome/browser/memory/tab_manager_delegate_chromeos.cc:628: MEMORY_LOG(ERROR)
<<
> "Killed " << *it << ", estimated "
> Is the log message identical in these two cases?  It might not hurt to mention
> "app" or "tab".

The << operator for TabManagerDelegate::Candidate provides different app- and
tab-specific information.

You can see the details around line 115-- let me know if you feel we need more
details or
if the difference should be more obvious.

[teravest, 2017-04-11 18:57:30]

The CQ bit was checked by teravest@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2017-04-11 18:57:58]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2017-04-11 20:08:55]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2017-04-11 20:08:56]

Dry run: This issue passed the CQ dry run.

[stevenjb, 2017-04-12 00:36:40]

lgtm

[teravest, 2017-04-12 14:30:22]

The CQ bit was checked by teravest@chromium.org

[teravest, 2017-04-12 14:30:23]

The patchset sent to the CQ was uploaded after l-g-t-m from derat@chromium.org,
chrisha@chromium.org
Link to the patchset: https://codereview.chromium.org/2811433002/#ps140001
(title: "longer message when unable to kill")

[commit-bot: I haz the power, 2017-04-12 14:30:49]

CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2017-04-12 14:36:32]

CQ is committing da patch.

Bot data: {"patchset_id": 140001, "attempt_start_ts": 1492007422793760,
"parent_rev": "b10caf8de873181849d28ea10bea9be564875e31", "commit_rev":
"53cb7fcf9db050cac655e47ff85d02daac7dbb22"}

[commit-bot: I haz the power, 2017-04-12 14:37:27]

Description was changed from

==========
Log app and tab discards.

On critical memory pressure, we already log entries at least for every
tab and extension and the corresponding memory usage. However, there's
no logging for the action that was taken in response.

This should help us understand discard behavior in feedback reports from
users.

BUG=709253
TEST=build
==========

to

==========
Log app and tab discards.

On critical memory pressure, we already log entries at least for every
tab and extension and the corresponding memory usage. However, there's
no logging for the action that was taken in response.

This should help us understand discard behavior in feedback reports from
users.

BUG=709253
TEST=build

Review-Url: https://codereview.chromium.org/2811433002
Cr-Commit-Position: refs/heads/master@{#464018}
Committed:
https://chromium.googlesource.com/chromium/src/+/53cb7fcf9db050cac655e47ff85d...
==========

[commit-bot: I haz the power, 2017-04-12 14:37:28]

Committed patchset #8 (id:140001) as
https://chromium.googlesource.com/chromium/src/+/53cb7fcf9db050cac655e47ff85d...