我司在做一款公交车上的车载应用,功能主要包含1.自动到离站语音播,2.报排班显示,3.Led,lcd,按键板等硬件通信 和其他功能不一一列举了。功能复杂度其实还挺高的,涉及 Jni,socke 长连接,多线程等技术栈。项目初期不是我开发的,而是由外包给别的团队。项目中期某些不可控因素,才把项目拉回来自己做。等项目完全上线能用后不久,同事也都离职了,剩下我一个人孤苦伶仃的去维护。熟悉架构,review兄弟们的代码逻辑。领导也多次要求我去熟悉他们的代码,看不懂的直接按自己的想法重构掉。这下好了, 我的2021年大半年的时间都在改进这个项目。
最近收到一些死机的报修反馈:机子卡死,不能自动报站。其实接到这种问题的第一反应是捞和trace。先说说我们的车载机设备的配置情况。系统android 6.0,双核cpu = 10年前的手机cpu的性能,内存 2G ddr3,存储16G。我对这样的硬件其实一直怨声载道。因为我们的应用复杂度 和实际运行对硬件的需求是挺高的,频繁的io,频繁线程切换。硬件部门给的回复是:跑我们的应用足够了。也许越差的硬件,越能激发一个coder的潜力吧。于是我把抱怨 就仅仅当成是抱怨。
回到上面提到的问题。通过查看日志立马发现了一些问题,问题1:
java.util.concurrent.TimeoutException: android.os.BinderProxy.finalize() timed out after 10 seconds
at android.os.BinderProxy.destroy(Native Method)
at android.os.BinderProxy.finalize(Binder.java:547)
at java.lang.Daemons$FinalizerDaemon.doFinalize(Daemons.java:202)
at java.lang.Daemons$FinalizerDaemon.run(Daemons.java:185)
at java.lang.Thread.run(Thread.java:818)
拿到以上异常信息后,我给产品的回复是系统卡死了,暂时无法定位问题原因。作为一个bug creator,pm听到我的回复肯定会说:一天时间够不够? 我也只能回复:no?problem !看完crash日志 一头雾水。继续查看运行时log。马上查到一些端倪(问题2):
1636519834003|I|BUSPAD_TAG|GWS=lat/lng: (30.24580982311159,120.20578926205371) ,精度:1.09,时间1636519812000 ,定位类型:1,speed = 4.01
1636519835008|I|BUSPAD_TAG|GWS=lat/lng: (30.24580982311159,120.20578926205371) ,精度:1.09,时间1636519812000 ,定位类型:1,speed = 4.01
1636519836000|I|BUSPAD_TAG|GWS=lat/lng: (30.24580982311159,120.20578926205371) ,精度:1.09,时间1636519812000 ,定位类型:1,speed = 4.01
1636519837001|I|BUSPAD_TAG|GWS=lat/lng: (30.24580982311159,120.20578926205371) ,精度:1.09,时间1636519812000 ,定位类型:1,speed = 4.01
1636519839936|I|BUSPAD_TAG|GWS=lat/lng: (30.24580982311159,120.20578926205371) ,精度:1.09,时间1636519812000 ,定位类型:1,speed = 4.01...
这些是连续的gps数据,我去!连续好几秒 中location都是同一个,时间戳都是一样的,这gps点都没动啊。难怪不会报站。tip:我们的自动报站算法是基于精准连续定位的前提。这种情况 是个人都知道肯定没法报站了。然后我又开始甩锅了,这锅给系统好?还是gps模组好?反正不能甩给 我自己写的代码。既然定位问题这么严重,去后台看看车辆的运行轨迹吧。看了轨迹我心里有底了。有另外一辆车和这辆车的编号冲突了。于是两辆车互相掉线,上线, 掉线,上线..。轨迹中有了两辆车的轨迹的交集。但是就是掉线重连,难道会导致软件卡死,甚至系统卡死嘛??我一脸懵逼的开始了我的卡顿元凶追寻之旅。
我在测试设备上 和 模拟器(android 10)上运行最新的代码。配置相同的测试编号。观察打印的日志,我发现测试设备和monitor只要有一方掉线,打印出来的gps点的日志的时间戳就会很不均匀,原本应该是1秒一次,顶多有个0-100ms左右的波动。软件掉线后的gps点不稳定到会有2s的误差,甚至2-4秒才出一个点。我坚信自己的gps处理逻辑不存在卡ui的情况。基本都把老的逻辑用协程优化了。可能真的是掉线会导致系统卡顿,然后影响gps模组和gpsprovicer的数据交互的效率。带着这份怀疑 ,我先从分析app的内存使用情况入手。模拟器的性能更好,我选择从模拟器着手分析。于是打开profiler。本来只是有点卡顿,一打开profile的那一刻,直接软件闪退,给了个OOM的crash log:
java.lang.OutOfMemoryError: Failed to allocate a 24 byte allocation with 16 free bytes and 16B until OOM, target footprint 16777216, growth limit 16777216
难道最上面提到的 java.util.concurrent.TimeoutException 和这个有关联?这是我第一反应。于是对测试设备也进行profile,果然 也产生了crash,不过它的crash 日志不是OOM 而是TimeoutException。基于我之前看的《深入理解Java虚拟机》这本书,我大胆猜测是6.0系统与10.0系统的gc机制,不一致,高版本JVM对OOM的定位更加清晰。
如何处理:java . util . concurrent。TimeoutException: android.os.BinderProxy.finalize()在10秒错误后超时? 这篇文章让我更加确信,TimeoutException是gc超时导致的,频繁FullGC,导致了系统的卡顿,不用说 肯定内存泄漏了嘛。“找到那个导致内存泄漏的根源” 是我此刻内心的唯一想法。
先定位问题:capture heap dump 。分析:heapdump中映入眼帘的第一反应是。这byte[] 数据也太大了,一半的应用内存都被它占用了。联想到掉线会引发卡顿,这部分数据应该是io操作 或者等待收发的数据队列(用的LinkedBlockQueen)产生的。点击byte[]这一行,查看更细致的对象内存分配情况。
看到Shallow Size那一列,1048576这个数据,我没仔细算,预估应该是 1024 * 1024的积。于是开始全局搜“1024 * 1024"。
看到这个搜索结果 我很惊喜,因为它和前一张图中的第三步指向的内存对象ReaderImpl完全吻合。那应该就是它了。这么快就找到它了,这也太简单了。但是这只是定位到了大对象,并不代表它就是内存泄漏的根源。于是我观察了几分钟的内存动态变化情况。自动触发gc的频率确实很高。多次执行heap dump后,这样的大对象果然越来越多。 大概大于8个后 就会出现OOM。这么说它就是最大的嫌疑人了。coder的必经之路:代码分析 ,代码优化。况且这些都是前辈祖传下来的。乘机好好理理。
优化前的代码贴出来了:
@Override
public void read() throws RuntimeException {
OriginalData originalData = new OriginalData();
try {
InputStream is = mInputStream;
DataInputStream input = new DataInputStream(is);
byte[] b = new byte[1024 * 1024];
ByteArrayOutputStream bos = new ByteArrayOutputStream();
int len = 0;
while (true) {
len = input.read(b);
bos.write(b, 0, len);
originalData.setBodyBytes(bos.toByteArray());
mStateSender.sendBroadcast(IOAction.ACTION_READ_COMPLETE, originalData);
bos.reset();
}
} catch (Exception e) {
ReadException readException = new ReadException(e);
throw readException;
}
}
看到这个while循环了吗,想想heap中不断增多的对象。细思极恐!!理论分析:socket io流 不需要多个reader对象。甚至在我们的项目中就不应该有多个reader对象。掉线重连后应该尝试重用该对象,或者把对象free掉 再重新new。 那我就从对象的创建入手 。
//io线程管理
private void resolveManager() throws IOException {
...
mManager = new IOThreadManager(...);
mManager.startEngine();
...
}
public IOThreadManager(...) {
...
initIO();
}
private void initIO() {
...
mReader = new ReaderImpl();
...
}
创建的流程也比较容易定位,reconnect后执行resolveManager(),执行链每次都会 new ReaderImpl();如果前一个对象来不及GC,那么出现两个对象,这是很正常的情况。极端情况下,频繁掉线重连,产生多个大对象 我也能理解。但是目前的重新连接的频率也控制在10s。所以 出现那么多没被回收的对象,那么肯定是有严重的泄漏问题。立马开始寻找泄漏的原因。回到上面贴的代码:
@Override
public void read() throws RuntimeException {
OriginalData originalData = new OriginalData();
try {
InputStream is = mInputStream;
DataInputStream input = new DataInputStream(is);
byte[] b = new byte[1024 * 1024];
ByteArrayOutputStream bos = new ByteArrayOutputStream();
int len = 0;
while (true) {
len = input.read(b);
bos.write(b, 0, len);
originalData.setBodyBytes(bos.toByteArray());
mStateSender.sendBroadcast(IOAction.ACTION_READ_COMPLETE, originalData);
bos.reset();
}
} catch (Exception e) {
ReadException readException = new ReadException(e);
throw readException;
}
}
在while循环中,如果io流断开。write操作会抛出异常。
java.net.SocketException: sendto failed: EPIPE (Broken pipe)
于是while循环断开。理论上这时候这个对象就没有用了。重连后 通过重新创建,然后继续执行read操作。难道有什么原因导致它又进入到read方法,如此反复。
@Override
public final void run() {
try {
isShutdown = false;
beforeLoop();
while (!isStop) {
this.runInLoopThread();
loopTimes++;
}
} catch (Exception e) {
if (ioException == null) {
ioException = e;
}
} finally {
isShutdown = true;
this.loopFinish(ioException);
ioException = null;
SLog.w(threadName + " is shutting down");
}
}
@Override
protected void runInLoopThread() throws IOException {
mReader.read();
}
看了好几遍其中的逻辑,似乎并没有什么问题。在异常的时候跳出read方法,抛异常给外部循环。最终停掉整个循环。此时的对象 应该是能被系统回收的。除非外层的run方法没有catch到异常。简单查看日志发现 ,read
方法中的自定义ReadException,并不是IOException。那么那runInLoopThread的throws IOException 改成throws RunTimeException。既然要优化,就把里面的实现逻辑全优化了。
优化后代码贴下面。
@Override
protected void runInLoopThread() throws RuntimeException {
//read操作进去前,先判断连通情况,减少不必要的对象的创建。否则直接抛异常,中断循环线程。
if (SocketManager.getInstance().isConnect()) {
mReader.read();
}else throw new ReadException();
}
ReaderImpl.java
//考虑到未来对象重用,把read方法中的对象提取出来复用
byte[] b = new byte[1024 * 1024];
OriginalData originalData = new OriginalData();
InputStream is = mInputStream;
DataInputStream input = null;
ByteArrayOutputStream bos = null ;
//接收byte数组
@Override
public void read() throws RuntimeException {
try {
// 如果复用 那么byte[]数据肯定得重置掉
ByteUtil.resetBytes(b);
input = new DataInputStream(is);
bos = new ByteArrayOutputStream();
int len = 0;
while (true) {
len = input.read(b);
if (len>0) {
bos.write(b, 0, len);
originalData.setBodyBytes(bos.toByteArray());
mStateSender.sendBroadcast(IOAction.ACTION_READ_COMPLETE, originalData);
bos.reset();
}
}
} catch (Exception e) {
ReadException readException = new ReadException(e);
b= null;
e.printStackTrace();
throw readException;
}finally {
if (bos!=null) {
try {
bos.reset();
} catch (Exception e) {
e.printStackTrace();
}
}
}
}
@Override
public void close() {
super.close();
// b对象应该是随着Reader对象一起回收的,这里置成null ,我就是想告诉系统,你随时来收了我吧。我绝对不浪费土地,此处的用处 应该不大。
b = null;
}
run一下,profile一下,嘿嘿嘿!!立马开心的跟领导汇报战况去了。
以上是我最近遇到的OOM问题定位和解决的过程。仅供问题定位和解决的一些思路。针对部分场景OOM问题的寻根也许这边文章能小小帮助到你。