When a low memory notification comes in, tab discarder should start discarding tab promptly to ease memory pressure. However we observed that sometimes on ChromeOS the gap is significant. It could be several seconds or even tens of seconds before tab discarder start working. The problem is that before the real tab discarder logic is run, a log line which dumps tab details and their memory usages could took lots of time:

memory::OomMemoryDetails::Log(title, callback); 
|callback| is PurgeMemoryAndDiscardTab() where the real discarding logic happens.
https://cs.chromium.org/chromium/src/chrome/browser/resource_coordinator/tab_manager.cc?rcl=d8cd8cb89ff6e2ca428a54a697166237b2f50d5d&l=312

OomMemoryDetails::Log() collects tab statistics asynchronously and calls the callback when all needed information is collected and printed. In certain situations, it could take a long time to collect all needed data.

In system_logs, lines like this report the time taken (in the parenthesis) to collect tabs information:
[1110:1110:0502/214952.638171:WARNING:oom_memory_details.cc(46)] Tab Discards Memory details (769 ms):

I collected 173 feedback report which contains OOM kill and here's the distribution of time taken:

time(seconds), occurrence, cumulative percentage
0 11278 62.47%
1 1824 72.58%
2 1199 79.22%
3 852 83.94%
4 686 87.74%
5 494 90.47%
6 490 93.19%
7 377 95.28%
8 190 96.33%
9 140 97.10%
10 70 97.49%
11 67 97.86%
12 59 98.19%
13 31 98.36%
14 21 98.48%
15 23 98.60%
16 23 98.73%
17 12 98.80%
18 23 98.93%
19 19 99.03%
20 11 99.09%
21 15 99.17%
22 13 99.25%
23 8 99.29%
24 6 99.32%
25 3 99.34%
26 9 99.39%
27 2 99.40%
28 4 99.42%
29 4 99.45%
30 7 99.48%
31 3 99.50%
32 7 99.54%
33 5 99.57%
34 5 99.60%
35 3 99.61%
36 7 99.65%
37 9 99.70%
38 2 99.71%
39 3 99.73%
40 2 99.74%
41 4 99.76%
42 4 99.78%
43 3 99.80%
44 1 99.81%
45 1 99.81%
46 2 99.82%
47 1 99.83%
48 2 99.84%
49 1 99.84%
50 1 99.85%
51 1 99.86%
52 1 99.86%
53 1 99.87%
54 1 99.87%
55 1 99.88%
56 2 99.89%
57 2 99.90%
58 2 99.91%
59 1 99.92%
60 2 99.93%
62 2 99.94%
63 2 99.95%
65 2 99.96%
66 1 99.97%
67 1 99.97%
68 1 99.98%
69 1 99.98%
70 2 99.99%
73 1 100.00%
Total 18053

That is, more than 37.5% of the tab info dump takes > 1s. 10% even takes > 5s. It's not acceptable.

The logging line should not block tab discarding from happening since we need immediate action when low memory signal comes in. I'm working on a CL to make the log line non-blocking. It should not be a ChromeOS only problem but apply to all platforms.

chrisha, fdoray
 Any comments?