I should add, maybe should split this into two bugs 
1) negative target memory to free
2) Discard happening too late, bursty

just that both issues showed at once for me in that log, and wanted to get expert opinions from the tab discard side

If I understand the behavior correctly the tab manager is checking the low-memory margin once a second. Cheng-Yu could you take a look at why sometimes it fails to find candidates to kill?

So why is it throttled to 1/sec ? It seems like we should revisit that decision because it often just kills several things but spreads it out over many seconds, which causes the jank to last longer.

Also, I turned on more logging and found that the negative numbers are coming from the target to free function.

Example:

[19391:19391:0420/190235.927998:VERBOSE2:tab_manager_delegate_chromeos.cc(585)] LowMemoryKillImpl
[19391:19391:0420/190235.928853:VERBOSE3:tab_manager_delegate_chromeos.cc(598)] Target memory to free: -4057 KB
[19391:19391:0420/190235.931356:ERROR:device_event_log_impl.cc(156)] [19:02:35.931] Memory: tab_manager_delegate_chromeos.cc:614 Killed app 26121 (com.google.android.gm), process_state ProcessState::CACHED_EMPTY, is_focused 0, lastActivityTime 3104092, process_type BACKGROUND_APP, estimated 34636 KB freed


It looks like there's at least one simple bug in TargetMemoryToFreeKB() where there's a race between when the low memory killer is called and when memory gets freed up:

// The logic of available memory calculation is copied from                                                                                                
// _is_low_mem_situation() in kernel file include/linux/low-mem-notify.h.                                                                                  
// Maybe we should let kernel report the number directly.                                                                                                  
int TabManagerDelegate::MemoryStat::TargetMemoryToFreeKB() {
  static const int kRamVsSwapWeight = 4;
  static const char kMinFilelistConfig[] = "/proc/sys/vm/min_filelist_kbytes";
  static const char kMinFreeKbytes[] = "/proc/sys/vm/min_free_kbytes";

  base::SystemMemoryInfoKB system_mem;
  base::GetSystemMemoryInfo(&system_mem);
  const int file_mem_kb = system_mem.active_file + system_mem.inactive_file;
  const int min_filelist_kb = ReadIntFromFile(kMinFilelistConfig, 0);
  const int min_free_kb = ReadIntFromFile(kMinFreeKbytes, 0);
  // Calculate current available memory in system.                                                                                                         
  // File-backed memory should be easy to reclaim, unless they're dirty.                                                                                   
  // TODO(cylee): On ChromeOS, kernel reports low memory condition when                                                                                    
  // available memory is low. The following formula duplicates the logic in                                                                                
  // kernel to calculate how much memory should be released. In the future,                                                                                
  // kernel should try to report the amount of memory to release directly to                                                                               
  // eliminate the duplication here.                                                                                                                       
  const int available_mem_kb = system_mem.free +
      file_mem_kb - system_mem.dirty - min_filelist_kb +
      system_mem.swap_free / kRamVsSwapWeight -
      min_free_kb;
  
  return LowMemoryMarginKB() - available_mem_kb;
}




we should probably check that the value of LowMemoryMarginKB is greater than available_mem_kb there, so we don't do an unnecessary tab kill

1. The negative value of "target memory to free" comes from a race between kernel and user space which I don't think we can eliminate? When memory gets low (below the configured margin) kernel raises a signal, there's always a time delta before tab discarder starts to work. When tab discarder kicks in, it tries to calculate the amount of memory to free so available memory goes back above the configured margin. The negative value here means that when tab discarder tries to kill tabs, kernel has already got enough memory reclaimed (e.g., via swapping). So tab discarder decides no need to kill tabs at the point.

There is a bug though, as #4 pointed out, that I should check the value of target_memory_to_free_kb before the loop, not only at the end of the loop
https://cs.chromium.org/chromium/src/chrome/browser/memory/tab_manager_delegate_chromeos.cc?rcl=bfce95b70e45ee513b3735e27660fbecc1eeea5f&l=633

The misleading error message "Unable to kill any candidates" also comes from the bug: Because tab discarder sees no need to kill tab, and it didn't distinguish the case from "couldn't find a tab to kill" 

I'll fix the problem.


2. The 1 second latency comes from the fact that Chrome doesn't "listen" on the low memory signal raised from kernel. Instead it "polls" every 1 second. I've also asked why it's designed to be so and it seems to be a legacy issue. Luigi knows the story better. I've always wanted to change it back to listen instead of polling. But frankly speaking I doubt it solve the problem fundamentally. See the point below.

3. The timing of when to raise the low memory signal has always been an open problem, I think all of us know the situation. Luigi and Ben has already tuned the margin and swap size on Caroline, but the problem doesn't seem to be fully resolved. There're some other bug traced the problem, but I don't think it's a bug in tab discarder.

re #5 thanks for the fix

From what I can tell, the reason there's a polling loop is because the kernel only supported one signal but Chrome wanted to support multiple memory pressure levels, and there are currently 2 levels: moderate and critical.  The kernel's notification is considered critical, but Chrome makes it's own calculation in the memory pressure listener and creates it's own moderate pressure notifications.  For that reason, Chrome is running a polling loop.

From what I've seen so far (might be wrong) I'm not sure if that moderate pressure notification is very useful or that it does anything at all.  I'm still investigating this.   


Another issue is that the memory pressure listener code is doing it's own calculation of available memory -- and this is inconsistent with the calculation in the kernel and the tab discarder.  I think this might cause the discarder to kick in too late.

Look at base/memory/memory_pressure_monitor_chromeos.cc MemoryPressureMonitor::CheckMemoryPressure

I have some ideas about how to change the structure of the system to get rid of this memory pressure calculation code in Chrome, so I'm going to write up a small doc.

QQ: how wasteful is the polling?  Any chance we could be smarter about the polling interval?  Measure the velocity of change and when we see lots of changes over a short period of time, we can increase the polling interval?

re #7 -- I think it's a waste most of the time, so I'm in favor of the old method which is calling select() on the low-mem-notify fd and blocking on that.  I'm going to put that into the small doc as well.

Ok, I did some more digging, and the moderate pressure notification definitely does something, so it's necessary.  

The gist of my idea is to centralize all of the memory calculations in the kernel.  So we'd need to change the low-mem interface to allow chrome to specify what level of memory pressure it cares about and have multiple levels. 
This is something Stefan Kuhne originally wanted, but we never got around to it.
To add to this, I also think the kernel should also tell chrome how much memory it needs to free up through the same interface.  

If we implement this, this means we can remove the logic of having the calculate the available memory in Chrome and keep in sync with the kernel's formula. 

I'm running with ToT chrome and I'm definitely seeing cases where the discarder is firing but fails to kill some tabs:

[19412:19412:0425/224508.056014:VERBOSE2:tab_manager_delegate_chromeos.cc(590)] LowMemoryKillImpl
[19412:19412:0425/224508.057349:ERROR:device_event_log_impl.cc(156)] [22:45:08.056] Memory: tab_manager_delegate_chromeos.cc:602 Target memory to free: 55940 KB
[19412:19412:0425/224508.058244:VERBOSE1:tab_manager_delegate_chromeos.cc(569)] LowMemoryKill for 3048
[19412:19412:0425/224508.058286:VERBOSE1:memory_kills_monitor.cc(53)] 1493185508058, LOW_MEMORY_KILL_APP
[19412:19412:0425/224508.058648:ERROR:device_event_log_impl.cc(156)] [22:45:08.058] Memory: tab_manager_delegate_chromeos.cc:621 Killed app 24959 (org.chromium.arc.tts), process_state ProcessState::SERVICE, is_focused 
0, lastActivityTime 17498154, process_type BACKGROUND_APP, estimated 15080 KB freed
[19412:19412:0425/224508.058776:ERROR:device_event_log_impl.cc(156)] [22:45:08.058] Memory: tab_manager_delegate_chromeos.cc:602 Target memory to free: 40860 KB
[19412:19412:0425/224508.060044:ERROR:device_event_log_impl.cc(156)] [22:45:08.059] Memory: tab_manager_delegate_chromeos.cc:639 Failed to kill tab 20026, process_type BACKGROUND_TAB
[19412:19412:0425/224508.060188:ERROR:device_event_log_impl.cc(156)] [22:45:08.060] Memory: tab_manager_delegate_chromeos.cc:602 Target memory to free: 40860 KB
[19412:19412:0425/224508.060341:ERROR:device_event_log_impl.cc(156)] [22:45:08.060] Memory: tab_manager_delegate_chromeos.cc:639 Failed to kill tab 0, process_type BACKGROUND_TAB
[19412:19412:0425/224508.060448:ERROR:device_event_log_impl.cc(156)] [22:45:08.060] Memory: tab_manager_delegate_chromeos.cc:602 Target memory to free: 40860 KB
[19412:19412:0425/224508.060582:ERROR:device_event_log_impl.cc(156)] [22:45:08.060] Memory: tab_manager_delegate_chromeos.cc:639 Failed to kill tab 0, process_type BACKGROUND_TAB
[19412:19412:0425/224508.060685:ERROR:device_event_log_impl.cc(156)] [22:45:08.060] Memory: tab_manager_delegate_chromeos.cc:602 Target memory to free: 40860 KB
[19412:19412:0425/224508.060817:ERROR:device_event_log_impl.cc(156)] [22:45:08.060] Memory: tab_manager_delegate_chromeos.cc:639 Failed to kill tab 0, process_type BACKGROUND_TAB
[19412:19412:0425/224508.060934:ERROR:device_event_log_impl.cc(156)] [22:45:08.060] Memory: tab_manager_delegate_chromeos.cc:602 Target memory to free: 40860 KB
[19412:19412:0425/224508.061075:ERROR:device_event_log_impl.cc(156)] [22:45:08.060] Memory: tab_manager_delegate_chromeos.cc:639 Failed to kill tab 0, process_type BACKGROUND_TAB
[19412:19412:0425/224508.061192:ERROR:device_event_log_impl.cc(156)] [22:45:08.061] Memory: tab_manager_delegate_chromeos.cc:602 Target memory to free: 40860 KB
[19412:19412:0425/224508.061337:ERROR:device_event_log_impl.cc(156)] [22:45:08.061] Memory: tab_manager_delegate_chromeos.cc:639 Failed to kill tab 20642, process_type BACKGROUND_TAB
[19412:19412:0425/224508.061445:ERROR:device_event_log_impl.cc(156)] [22:45:08.061] Memory: tab_manager_delegate_chromeos.cc:602 Target memory to free: 40860 KB
[19412:19412:0425/224508.062453:ERROR:device_event_log_impl.cc(156)] [22:45:08.062] Memory: tab_manager_delegate_chromeos.cc:639 Failed to kill tab 20031, process_type BACKGROUND_TAB
[19412:19412:0425/224508.062570:ERROR:device_event_log_impl.cc(156)] [22:45:08.062] Memory: tab_manager_delegate_chromeos.cc:602 Target memory to free: 40860 KB
[19412:19412:0425/224508.063489:ERROR:device_event_log_impl.cc(156)] [22:45:08.063] Memory: tab_manager_delegate_chromeos.cc:639 Failed to kill tab 20031, process_type BACKGROUND_TAB
[19412:19412:0425/224508.063603:ERROR:device_event_log_impl.cc(156)] [22:45:08.063] Memory: tab_manager_delegate_chromeos.cc:602 Target memory to free: 40860 KB
[19412:19412:0425/224508.064415:ERROR:device_event_log_impl.cc(156)] [22:45:08.064] Memory: tab_manager_delegate_chromeos.cc:639 Failed to kill tab 20031, process_type BACKGROUND_TAB
[19412:19412:0425/224508.064547:ERROR:device_event_log_impl.cc(156)] [22:45:08.064] Memory: tab_manager_delegate_chromeos.cc:602 Target memory to free: 40860 KB
[19412:19412:0425/224508.067197:ERROR:device_event_log_impl.cc(156)] [22:45:08.067] Memory: tab_manager_delegate_chromeos.cc:639 Failed to kill tab 22155, process_type BACKGROUND_TAB
[19412:19412:0425/224508.067373:ERROR:device_event_log_impl.cc(156)] [22:45:08.067] Memory: tab_manager_delegate_chromeos.cc:602 Target memory to free: 40860 KB
[19412:19412:0425/224508.264450:VERBOSE1:memory_kills_monitor.cc(53)] 1493185508264, LOW_MEMORY_KILL_TAB
[19412:19412:0425/224508.264953:ERROR:device_event_log_impl.cc(156)] [22:45:08.264] Memory: tab_manager_delegate_chromeos.cc:636 Killed tab 22184, process_type BACKGROUND_TAB, estimated 3193640 KB freed
[19412:19412:0425/224508.265337:ERROR:device_event_log_impl.cc(156)] [22:45:08.264] Memory: tab_manager_delegate_chromeos.cc:602 Target memory to free: -3152780 KB


I'm not yet sure why this happens so I need to dig further on that

FYI I was able to reproduce the "Failed to kill tab XXXXX" pretty well using telemetry tab_switching test:

./tools/perf/run_benchmark --remote=${IP} --browser=cros-chrome tab_switching.typical_25  --output-format=json --tabset-repeat=5 

the key parameter is the tabset-repeat=5 which will open 25 x 5 or 100 tabs

I see that some tabs do get killed, but I also pretty often see the "Failed to kill tab" messages as well

I also found the problem. It's that one of the two function returns 0
 
CanDiscardTab()
https://cs.chromium.org/chromium/src/chrome/browser/memory/tab_manager.cc?rcl=2582adf8aedbc7c9538aec544f80bf6379b11cc5&l=308

DiscardWebContentsAt()
https://cs.chromium.org/chromium/src/chrome/browser/memory/tab_manager.cc?rcl=2582adf8aedbc7c9538aec544f80bf6379b11cc5&l=761

I haven't checked which condition it is, but I noticed that often it failed to kill tab with renderer_handle (PID) 0. It means the tab is not a regular tab ? (Extension? special process?) Not sure what it is yet, but given there're some legitimated case where a tab could not be killed, it may be one of them.
I'll check it later

I am seeing this with chrome 60.0.3080.3 and recent ToT ChromeOS.  Chrome user log is attached.

I have about 40 chrome tabs open and 5 or 6 android apps.  There should be plenty of killable tab/apps.  Maybe the wrong log message is not fixed yet?

[1589:1589:0505/121239.973973:ERROR:device_event_log_impl.cc(156)] [12:12:39.973] Memory: tab_manager_delegate_chromeos.cc:614 Killed app 8643 (com.google.process.gapps), process_state ProcessState::CACHED_EMPTY, is_focused 0, lastActivityTime 477984, process_type BACKGROUND_APP, estimated 26664 KB freed
[1589:1589:0505/121239.992403:ERROR:device_event_log_impl.cc(156)] [12:12:39.992] Memory: tab_manager_delegate_chromeos.cc:628 Killed tab 4362, process_type BACKGROUND_TAB, estimated 96264 KB freed
[1589:1589:0505/121240.150725:WARNING:oom_memory_details.cc(46)] Tab Discards Memory details (155 ms):
Tab [Oklahoma City News, Sports, Weather & Entertainment | News OK|Google Keep] 311 MB private, 315 MB shared, 44 MB swapped, 115 FDs open of 2048
Tab [CNNMoney - Business, financial and personal finance news|The New York Times - Breaking News, World News & Multimedia] 230 MB private, 232 MB shared, 164 MB swapped, 98 FDs open of 2048
Browser 220 MB private, 225 MB shared, 102 MB swapped, 518 FDs open of 2048
Tab [CNN Style - Fashion, design, art, architecture and luxury - CNN.com|Entertainment News - Celebrities, Movies, TV, Music - CNN.com|Home | University of California, Berkeley] 203 MB private, 204 MB shared, 178 MB swapped, 95 FDs open of 2048
Tab [Washington Post: Breaking News, World, US, DC News & Analysis - The Washington Post|Video News - CNN.com] 202 MB private, 205 MB shared, 173 MB swapped, 102 FDs open of 2048
Tab [U.S. News - CNN.com|CNNPolitics - Political News, Analysis and Opinion] 197 MB private, 198 MB shared, 177 MB swapped, 93 FDs open of 2048
Tab [Inbox (19) - semenzatotest@gmail.com - Gmail] 177 MB private, 182 MB shared, 22 MB swapped, 85 FDs open of 2048
Tab [Google News|World News - CNN.com|The White House | whitehouse.gov] 176 MB private, 180 MB shared, 43 MB swapped, 106 FDs open of 2048
GPU [] 167 MB private, 171 MB shared, 103 MB swapped, 308 FDs open of 2048
Tab [Opinion, Commentary, Analysis - CNN.com|Liberal Arts College | Colleges in California | Mills College] 158 MB private, 160 MB shared, 138 MB swapped, 96 FDs open of 2048
Tab [Untitled|Offers – Google Chromebooks|The Wall Street Journal & Breaking News, Business, Financial and Economic News, World News and Video] 154 MB private, 158 MB shared, 91 MB swapped, 110 FDs open of 2048
Tab [Travel News - CNN.com] 138 MB private, 139 MB shared, 121 MB swapped, 91 FDs open of 2048
Tab [(4) YouTube|Google Hangouts|My Drive - Google Drive] 132 MB private, 139 MB shared, 19 MB swapped, 93 FDs open of 2048
Tab [Health News - CNN.com] 129 MB private, 130 MB shared, 47 MB swapped, 91 FDs open of 2048
Tab [CNN - Breaking News, Latest News and Videos] 126 MB private, 127 MB shared, 114 MB swapped, 91 FDs open of 2048
Tab [Photos - Google Photos|Bleacher Report | Sports. Highlights. News. Now.] 119 MB private, 120 MB shared, 102 MB swapped, 93 FDs open of 2048
Tab [2018 Equinox: Fuel Efficient SUV | Chevrolet] 113 MB private, 115 MB shared, 93 MB swapped, 89 FDs open of 2048
Tab [My Drive - Google Drive] 111 MB private, 118 MB shared, 31 MB swapped, 85 FDs open of 2048
Tab [Google Play] 99 MB private, 105 MB shared, 18 MB swapped, 89 FDs open of 2048
Tab [Technology - Tech News - CNNMoney] 84 MB private, 86 MB shared, 72 MB swapped, 89 FDs open of 2048
Tab [Google Calendar - Week of 30 Apr 2017] 81 MB private, 83 MB shared, 56 MB swapped, 85 FDs open of 2048
Tab [Williams College] 55 MB private, 57 MB shared, 53 MB swapped, 92 FDs open of 2048
Tab [Chrome Web Store - drive] 51 MB private, 52 MB shared, 50 MB swapped, 88 FDs open of 2048
Extension [Google Keep Chrome Extension - CORP] 44 MB private, 45 MB shared, 36 MB swapped, 80 FDs open of 2048
Tab (Chrome) [chrome://flags] 42 MB private, 43 MB shared, 41 MB swapped, 84 FDs open of 2048
Tab (Chrome) [chrome://flags] 42 MB private, 43 MB shared, 42 MB swapped, 88 FDs open of 2048
Tab (Chrome) [chrome://app-list] 27 MB private, 29 MB shared, 27 MB swapped, 78 FDs open of 2048
Zygote 19 MB private, 20 MB shared, 19 MB swapped, 58 FDs open of 2048
Graphics 1.5 GB
[1589:1589:0505/121240.159721:ERROR:device_event_log_impl.cc(156)] [12:12:40.159] Memory: tab_manager_delegate_chromeos.cc:637 Low memory: Unable to kill any candidates. Attempted to free -55181 KB

Deleted: chrome 101 KB

chrome 101 KB View Download

That can sometimes happen if there's swapping going on at the same time and
it frees up memory before the discarder runs...this may mean the discarder
is too slow at times probably because of the polling

#14 yes, but we really need to change the log message.  Things are confusing enough without adding to it.

#15 The log message was revised in this commit:
https://codereview.chromium.org/2843633002

#13 Your ChromeOS version is before my fix. My fixing CL is present in 60.0.3083.0.
The rationale is explained in #5.

#14 Yes the polling is like to worsen the problem, but there's always a gap between kernel and chrome process so it's unlikely to avoid totally.

#15 It should have been fixed in a newer version.

re #12 -- I investigated the tab discard failing case by running:
./tools/perf/run_benchmark --remote=${IP} --browser=cros-chrome -d tab_switching.typical_25   --tabset-repeat=5

on ToT with Caroline
This test is more than sufficient to cause a lot of discard activity

it looks like from what I can tell, id 0 is valid, and the messages usually indicate the discard failed because the tab was already discarded.  It seems when we iterate through candidates, we don't remove already discarded tabs.

This may be mostly harmless but causes a lot of erroneous failed to kill messages, so might be worth cleaning up.

Gotcha. Thanks for the investigation.

This feedback report:

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

has something like 920 tab discards.  I compared the tab lists in subsequent discards (since the log doesn't specify which tab was discarded, if any) and noticed that for 648 of them the before/after list of tabs/extensions/etc. is identical.

The user was on a caroline with chrome version 58.0.3029.98 and chrome os version R58-9334.64.0.

I think things are much much better on R60 marking fixed but will continue investigations -- based on Feedback like the one in #21 it's definitely worth merging crrev.com/467044 back

I've filed going to file another bug for the feedback report because the LRU seems broken (though we can't quite tell from the logs)

 crbug.com/721629 

#22 Shouldn't we request merging crrev.com/467044 back to M59 on this bug?

 crbug.com/721629  looks a different problem to me. 

is it too late to merge this into 58? or is this not an issue on 58? 

Since TPE is already Saturday, I'll merge crrev.com/467044 into M59. cylee@, let me know if you're already working on it.

Hi Sonny,
  Thinking it twice, crrev.com/467044 doesn't help much. It solves a bug explained #5, but the bug definitely won't cause an excessive amount of tab discard as described #21. So I won't merge back this CL to M59 and M58.  (Actually I've tried to merge it back to M59, but yusukes has merged some other patches back so there're some merge conflicts. I decide not to mess things up).

  There're two bugs forked from this bug:
   crbug.com/721629 : Looks more like we're really out of memory in that case.
   crbug.com/721632 : I'll fix the log problem.

(chatted with cylee@ and merged crrev.com/467044 into M59 for now.)

https://chromium.googlesource.com/chromium/src/+/9b4f6297310746426a648f5c9de4a21ce236fc37

Your change meets the bar and is auto-approved for M59. Please go ahead and merge the CL to branch 3071 manually. Please contact milestone owner if you have questions.
Owners: amineer@(Android), cmasso@(iOS), gkihumba@(ChromeOS), Abdul Syed@(Desktop)

For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot

This issue has been approved for a merge. Please merge the fix to any appropriate branches as soon as possible!

If all merges have been completed, please remove any remaining Merge-Approved labels from this issue.

Thanks for your time! To disable nags, add the Disable-Nags label.

For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot

I think this has all been merged now -- marking Merged