From 48f93dabe05d8628c451beca78bc6aef51ebcf70 Mon Sep 17 00:00:00 2001 From: Vova Sharaienko Date: Sat, 24 Apr 2021 00:26:56 +0000 Subject: [PATCH 1/2] ActivityManagerService: reroute lmkd atoms logging - Added support to subscribe for a lmkd LMK_ASYNC_EVENT_STAT event - Added processing LMK_KILL_OCCURRED and LMK_STATE_CHANGED packets with logging to statsd - Added statsd auto-generated code wrapping the statsd logging Bug: 184698933 Test: lmkd_unit_test - test check_for_oom tests lmkd message send to AMS Test: statsd_testdrive 51 54 to inspect statsd logged atoms data Change-Id: I69ef1a9daa5532244a15665bff06d0ad6b370869 Merged-In: I69ef1a9daa5532244a15665bff06d0ad6b370869 --- .../com/android/server/am/LmkdConnection.java | 8 +- .../android/server/am/LmkdStatsReporter.java | 114 ++++++++++++++++++ .../com/android/server/am/ProcessList.java | 30 ++++- 3 files changed, 149 insertions(+), 3 deletions(-) create mode 100644 services/core/java/com/android/server/am/LmkdStatsReporter.java diff --git a/services/core/java/com/android/server/am/LmkdConnection.java b/services/core/java/com/android/server/am/LmkdConnection.java index f41c36404c501..4cffd6f5b08c5 100644 --- a/services/core/java/com/android/server/am/LmkdConnection.java +++ b/services/core/java/com/android/server/am/LmkdConnection.java @@ -43,8 +43,12 @@ import java.nio.ByteBuffer; public class LmkdConnection { private static final String TAG = TAG_WITH_CLASS_NAME ? "LmkdConnection" : TAG_AM; - // lmkd reply max size in bytes - private static final int LMKD_REPLY_MAX_SIZE = 12; + /** + * Max LMKD reply packet length in bytes + * Used to hold the data for the statsd atoms logging + * Must be in sync with statslog.h + */ + private static final int LMKD_REPLY_MAX_SIZE = 214; // connection listener interface interface LmkdConnectionListener { diff --git a/services/core/java/com/android/server/am/LmkdStatsReporter.java b/services/core/java/com/android/server/am/LmkdStatsReporter.java new file mode 100644 index 0000000000000..8ffec914efe6e --- /dev/null +++ b/services/core/java/com/android/server/am/LmkdStatsReporter.java @@ -0,0 +1,114 @@ +/* + * Copyright (C) 2021 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.android.server.am; + +import static com.android.server.am.ActivityManagerDebugConfig.TAG_AM; +import static com.android.server.am.ActivityManagerDebugConfig.TAG_WITH_CLASS_NAME; + +import android.util.Slog; + +import com.android.internal.util.FrameworkStatsLog; + +import java.io.ByteArrayInputStream; +import java.io.DataInputStream; +import java.io.IOException; +import java.nio.ByteBuffer; + +/** + * Activity manager communication with lmkd data handling and statsd atom logging + */ +public final class LmkdStatsReporter { + + static final String TAG = TAG_WITH_CLASS_NAME ? "LmkdStatsReporter" : TAG_AM; + + public static final int KILL_OCCURRED_MSG_SIZE = 80; + public static final int STATE_CHANGED_MSG_SIZE = 8; + + private static final int PRESSURE_AFTER_KILL = 0; + private static final int NOT_RESPONDING = 1; + private static final int LOW_SWAP_AND_THRASHING = 2; + private static final int LOW_MEM_AND_SWAP = 3; + private static final int LOW_MEM_AND_THRASHING = 4; + private static final int DIRECT_RECL_AND_THRASHING = 5; + private static final int LOW_MEM_AND_SWAP_UTIL = 6; + + /** + * Processes the LMK_KILL_OCCURRED packet data + * Logs the event when LMKD kills a process to reduce memory pressure. + * Code: LMK_KILL_OCCURRED = 51 + */ + public static void logKillOccurred(ByteBuffer dataReceived) { + DataInputStream inputData = new DataInputStream( + new ByteArrayInputStream(dataReceived.array())); + + try { + //read first int which denotes the message type + final int msgType = inputData.readInt(); + final long pgFault = inputData.readLong(); + final long pgMajFault = inputData.readLong(); + final long rssInBytes = inputData.readLong(); + final long cacheInBytes = inputData.readLong(); + final long swapInBytes = inputData.readLong(); + final long processStartTimeNS = inputData.readLong(); + final int uid = inputData.readInt(); + final int oomScore = inputData.readInt(); + final int minOomScore = inputData.readInt(); + final int freeMemKb = inputData.readInt(); + final int freeSwapKb = inputData.readInt(); + final int killReason = inputData.readInt(); + final String procName = inputData.readUTF(); + + FrameworkStatsLog.write(FrameworkStatsLog.LMK_KILL_OCCURRED, uid, procName, oomScore, + pgFault, pgMajFault, rssInBytes, cacheInBytes, swapInBytes, processStartTimeNS, + minOomScore, freeMemKb, freeSwapKb, mapKillReason(killReason)); + } catch (IOException e) { + Slog.e(TAG, "Invalid buffer data. Failed to log LMK_KILL_OCCURRED"); + return; + } + } + + /** + * Processes the LMK_STATE_CHANGED packet + * Logs the change in LMKD state which is used as start/stop boundaries for logging + * LMK_KILL_OCCURRED event. + * Code: LMK_STATE_CHANGED = 54 + */ + public static void logStateChanged(int state) { + FrameworkStatsLog.write(FrameworkStatsLog.LMK_STATE_CHANGED, state); + } + + private static int mapKillReason(int reason) { + switch (reason) { + case PRESSURE_AFTER_KILL: + return FrameworkStatsLog.LMK_KILL_OCCURRED__REASON__PRESSURE_AFTER_KILL; + case NOT_RESPONDING: + return FrameworkStatsLog.LMK_KILL_OCCURRED__REASON__NOT_RESPONDING; + case LOW_SWAP_AND_THRASHING: + return FrameworkStatsLog.LMK_KILL_OCCURRED__REASON__LOW_SWAP_AND_THRASHING; + case LOW_MEM_AND_SWAP: + return FrameworkStatsLog.LMK_KILL_OCCURRED__REASON__LOW_MEM_AND_SWAP; + case LOW_MEM_AND_THRASHING: + return FrameworkStatsLog.LMK_KILL_OCCURRED__REASON__LOW_MEM_AND_THRASHING; + case DIRECT_RECL_AND_THRASHING: + return FrameworkStatsLog.LMK_KILL_OCCURRED__REASON__DIRECT_RECL_AND_THRASHING; + case LOW_MEM_AND_SWAP_UTIL: + return FrameworkStatsLog.LMK_KILL_OCCURRED__REASON__LOW_MEM_AND_SWAP_UTIL; + default: + return FrameworkStatsLog.LMK_KILL_OCCURRED__REASON__UNKNOWN; + } + } +} diff --git a/services/core/java/com/android/server/am/ProcessList.java b/services/core/java/com/android/server/am/ProcessList.java index 444418cd3d6e9..c225913979f6a 100644 --- a/services/core/java/com/android/server/am/ProcessList.java +++ b/services/core/java/com/android/server/am/ProcessList.java @@ -316,18 +316,25 @@ public final class ProcessList { // LMK_GETKILLCNT // LMK_SUBSCRIBE // LMK_PROCKILL + // LMK_UPDATE_PROPS + // LMK_KILL_OCCURRED + // LMK_STATE_CHANGED static final byte LMK_TARGET = 0; static final byte LMK_PROCPRIO = 1; static final byte LMK_PROCREMOVE = 2; static final byte LMK_PROCPURGE = 3; static final byte LMK_GETKILLCNT = 4; static final byte LMK_SUBSCRIBE = 5; - static final byte LMK_PROCKILL = 6; // Note: this is an unsolicated command + static final byte LMK_PROCKILL = 6; // Note: this is an unsolicited command + static final byte LMK_UPDATE_PROPS = 7; + static final byte LMK_KILL_OCCURRED = 8; // Msg to subscribed clients on kill occurred event + static final byte LMK_STATE_CHANGED = 9; // Msg to subscribed clients on state changed // Low Memory Killer Daemon command codes. // These must be kept in sync with async_event_type definitions in lmkd.h // static final int LMK_ASYNC_EVENT_KILL = 0; + static final int LMK_ASYNC_EVENT_STAT = 1; // lmkd reconnect delay in msecs private static final long LMKD_RECONNECT_DELAY_MS = 1000; @@ -781,6 +788,7 @@ public final class ProcessList { if (receivedLen < 4) { return false; } + switch (dataReceived.getInt(0)) { case LMK_PROCKILL: if (receivedLen != 12) { @@ -789,6 +797,20 @@ public final class ProcessList { mAppExitInfoTracker.scheduleNoteLmkdProcKilled( dataReceived.getInt(4), dataReceived.getInt(8)); return true; + case LMK_KILL_OCCURRED: + if (receivedLen < LmkdStatsReporter.KILL_OCCURRED_MSG_SIZE) { + return false; + } + dataReceived.position(4); + LmkdStatsReporter.logKillOccurred(dataReceived); + return true; + case LMK_STATE_CHANGED: + if (receivedLen != LmkdStatsReporter.STATE_CHANGED_MSG_SIZE) { + return false; + } + LmkdStatsReporter.logStateChanged( + dataReceived.getInt(4)); + return true; default: return false; } @@ -1433,6 +1455,12 @@ public final class ProcessList { buf.putInt(LMK_SUBSCRIBE); buf.putInt(LMK_ASYNC_EVENT_KILL); ostream.write(buf.array(), 0, buf.position()); + + // Subscribe for stats event notifications + buf = ByteBuffer.allocate(4 * 2); + buf.putInt(LMK_SUBSCRIBE); + buf.putInt(LMK_ASYNC_EVENT_STAT); + ostream.write(buf.array(), 0, buf.position()); } catch (IOException ex) { return false; } From a89d79ba31522f8180b4918f51d928552faf470b Mon Sep 17 00:00:00 2001 From: Vova Sharaienko Date: Sat, 8 May 2021 00:37:25 +0000 Subject: [PATCH 2/2] AMS: added caching DataInputStream object DataInputStream is cached for the lmkd socket communication Since the LmkdConnection ByteBuffer is allocated once, no need to dynamically allocate DataInputStream, just do a reset() before using Bug: 184698933 Test: lmkd_unit_test - test check_for_oom tests lmkd message send to AMS Test: statsd_testdrive 51 54 to inspect statsd logged atoms data Change-Id: I9b65d82618654d59236c79be8cd8da66bc90c91c Merged-In: I9b65d82618654d59236c79be8cd8da66bc90c91c --- .../com/android/server/am/LmkdConnection.java | 50 ++++++++++------- .../android/server/am/LmkdStatsReporter.java | 9 +-- .../com/android/server/am/ProcessList.java | 56 +++++++++++-------- 3 files changed, 64 insertions(+), 51 deletions(-) diff --git a/services/core/java/com/android/server/am/LmkdConnection.java b/services/core/java/com/android/server/am/LmkdConnection.java index 4cffd6f5b08c5..1ecb9eb817090 100644 --- a/services/core/java/com/android/server/am/LmkdConnection.java +++ b/services/core/java/com/android/server/am/LmkdConnection.java @@ -31,6 +31,8 @@ import com.android.internal.annotations.GuardedBy; import libcore.io.IoUtils; +import java.io.ByteArrayInputStream; +import java.io.DataInputStream; import java.io.FileDescriptor; import java.io.IOException; import java.io.InputStream; @@ -74,7 +76,7 @@ public class LmkdConnection { * @param receivedLen Size of the data received * @return True if the message has been handled correctly, false otherwise. */ - boolean handleUnsolicitedMessage(ByteBuffer dataReceived, int receivedLen); + boolean handleUnsolicitedMessage(DataInputStream inputData, int receivedLen); } private final MessageQueue mMsgQueue; @@ -99,6 +101,10 @@ public class LmkdConnection { private final ByteBuffer mInputBuf = ByteBuffer.allocate(LMKD_REPLY_MAX_SIZE); + // Input stream to parse the incoming data + private final DataInputStream mInputData = new DataInputStream( + new ByteArrayInputStream(mInputBuf.array())); + // object to protect mReplyBuf and to wait/notify when reply is received private final Object mReplyBufLock = new Object(); @@ -190,26 +196,32 @@ public class LmkdConnection { private void processIncomingData() { int len = read(mInputBuf); if (len > 0) { - synchronized (mReplyBufLock) { - if (mReplyBuf != null) { - if (mListener.isReplyExpected(mReplyBuf, mInputBuf, len)) { - // copy into reply buffer - mReplyBuf.put(mInputBuf.array(), 0, len); - mReplyBuf.rewind(); - // wakeup the waiting thread - mReplyBufLock.notifyAll(); - } else if (!mListener.handleUnsolicitedMessage(mInputBuf, len)) { - // received unexpected packet - // treat this as an error - mReplyBuf = null; - mReplyBufLock.notifyAll(); - Slog.e(TAG, "Received an unexpected packet from lmkd"); + try { + // reset InputStream to point into mInputBuf.array() begin + mInputData.reset(); + synchronized (mReplyBufLock) { + if (mReplyBuf != null) { + if (mListener.isReplyExpected(mReplyBuf, mInputBuf, len)) { + // copy into reply buffer + mReplyBuf.put(mInputBuf.array(), 0, len); + mReplyBuf.rewind(); + // wakeup the waiting thread + mReplyBufLock.notifyAll(); + } else if (!mListener.handleUnsolicitedMessage(mInputData, len)) { + // received unexpected packet + // treat this as an error + mReplyBuf = null; + mReplyBufLock.notifyAll(); + Slog.e(TAG, "Received an unexpected packet from lmkd"); + } + } else if (!mListener.handleUnsolicitedMessage(mInputData, len)) { + // received asynchronous communication from lmkd + // but we don't recognize it. + Slog.w(TAG, "Received an unexpected packet from lmkd"); } - } else if (!mListener.handleUnsolicitedMessage(mInputBuf, len)) { - // received asynchronous communication from lmkd - // but we don't recognize it. - Slog.w(TAG, "Received an unexpected packet from lmkd"); } + } catch (IOException e) { + Slog.e(TAG, "Failed to parse lmkd data buffer. Size = " + len); } } } diff --git a/services/core/java/com/android/server/am/LmkdStatsReporter.java b/services/core/java/com/android/server/am/LmkdStatsReporter.java index 8ffec914efe6e..c702d780bd6b9 100644 --- a/services/core/java/com/android/server/am/LmkdStatsReporter.java +++ b/services/core/java/com/android/server/am/LmkdStatsReporter.java @@ -23,10 +23,8 @@ import android.util.Slog; import com.android.internal.util.FrameworkStatsLog; -import java.io.ByteArrayInputStream; import java.io.DataInputStream; import java.io.IOException; -import java.nio.ByteBuffer; /** * Activity manager communication with lmkd data handling and statsd atom logging @@ -51,13 +49,8 @@ public final class LmkdStatsReporter { * Logs the event when LMKD kills a process to reduce memory pressure. * Code: LMK_KILL_OCCURRED = 51 */ - public static void logKillOccurred(ByteBuffer dataReceived) { - DataInputStream inputData = new DataInputStream( - new ByteArrayInputStream(dataReceived.array())); - + public static void logKillOccurred(DataInputStream inputData) { try { - //read first int which denotes the message type - final int msgType = inputData.readInt(); final long pgFault = inputData.readLong(); final long pgMajFault = inputData.readLong(); final long rssInBytes = inputData.readLong(); diff --git a/services/core/java/com/android/server/am/ProcessList.java b/services/core/java/com/android/server/am/ProcessList.java index c225913979f6a..e9b014621e70e 100644 --- a/services/core/java/com/android/server/am/ProcessList.java +++ b/services/core/java/com/android/server/am/ProcessList.java @@ -125,6 +125,7 @@ import com.android.server.wm.WindowManagerService; import dalvik.system.VMRuntime; +import java.io.DataInputStream; import java.io.File; import java.io.FileDescriptor; import java.io.IOException; @@ -783,37 +784,44 @@ public final class ProcessList { } @Override - public boolean handleUnsolicitedMessage(ByteBuffer dataReceived, + public boolean handleUnsolicitedMessage(DataInputStream inputData, int receivedLen) { if (receivedLen < 4) { return false; } - switch (dataReceived.getInt(0)) { - case LMK_PROCKILL: - if (receivedLen != 12) { + try { + switch (inputData.readInt()) { + case LMK_PROCKILL: + if (receivedLen != 12) { + return false; + } + final int pid = inputData.readInt(); + final int uid = inputData.readInt(); + mAppExitInfoTracker.scheduleNoteLmkdProcKilled(pid, uid); + return true; + case LMK_KILL_OCCURRED: + if (receivedLen + < LmkdStatsReporter.KILL_OCCURRED_MSG_SIZE) { + return false; + } + LmkdStatsReporter.logKillOccurred(inputData); + return true; + case LMK_STATE_CHANGED: + if (receivedLen + != LmkdStatsReporter.STATE_CHANGED_MSG_SIZE) { + return false; + } + final int state = inputData.readInt(); + LmkdStatsReporter.logStateChanged(state); + return true; + default: return false; - } - mAppExitInfoTracker.scheduleNoteLmkdProcKilled( - dataReceived.getInt(4), dataReceived.getInt(8)); - return true; - case LMK_KILL_OCCURRED: - if (receivedLen < LmkdStatsReporter.KILL_OCCURRED_MSG_SIZE) { - return false; - } - dataReceived.position(4); - LmkdStatsReporter.logKillOccurred(dataReceived); - return true; - case LMK_STATE_CHANGED: - if (receivedLen != LmkdStatsReporter.STATE_CHANGED_MSG_SIZE) { - return false; - } - LmkdStatsReporter.logStateChanged( - dataReceived.getInt(4)); - return true; - default: - return false; + } + } catch (IOException e) { + Slog.e(TAG, "Invalid buffer data. Failed to log LMK_KILL_OCCURRED"); } + return false; } } );