最近遇到了一个线程阻塞的问题,分析的过程比较有代表性,这里做个总结分享下。
测试报的问题是: 概率性出现开机的前几分钟我们的服务不可用。
查看日志发现开机之后的几分钟之内mqtt库不断在断开、重连broker。MqttCallback.disconnected一直在被调用,而且还能看到发布消息也失败了:
12-28 18:27:18.948 812 884 E LinJwDemoMqtt: publish failed : 等待来自服务器的响应时超时 (32000)
12-28 18:27:18.948 812 884 E LinJwDemoMqtt: at d.c.a.a.a.l(Unknown Source:9)
12-28 18:27:18.948 812 884 E LinJwDemoMqtt: at g.b.a.a.a.l.b.a(:4)
12-28 18:27:18.948 812 884 E LinJwDemoMqtt: at g.b.a.a.a.k$b.run(:8)
12-28 18:27:18.948 812 884 E LinJwDemoMqtt: at java.util.TimerThread.mainLoop(Timer.java:562)
12-28 18:27:18.948 812 884 E LinJwDemoMqtt: at java.util.TimerThread.run(Timer.java:512)
过了几分钟之后就恢复了,能够和mqtt broker正常通讯。
正常情况下断开连接应该是网络问题,但是发生如果是网络问题应该是一直连不上,而不会连接上又断开连接。除非刚开机的时候系统网络模块异常抽风,从日志上看网络是正常的,而且在broker的日志里面看到的是client主动断开的连接:
2022-12-28T18:27:19: Client LinJwDemoMqtt_1672223154916 closed its connection.
Long monitor contention
这样看来问题还是出在客户端,仔细翻看首次出现异常和恢复正常的那段时间的日志,在恢复正常的时候发现了这样的打印:
Long monitor contention with owner MQTT Call: LinJwDemoMqtt_1672223154916 (1252) at void java.lang.Thread.sleep(java.lang.Object, long, int)(Thread.java:-2) waiters=0 in java.util.List d.d.e.c.k.b.f.f(java.lang.String, java.lang.String) for 270.749s
这行日志的意思是tid为1252的LinJwDemoMqtt_1672223154916线程长期持有了对象的monitor,导致d.d.e.c.k.b.f.f这个方法等待了270.749秒才获取到线程锁。
这里的monitor指的就是synchronized关键字的底层实现。正常情况对一段代码进行加锁应该是一个短时间的行为,一旦某个线程长时间持有对象锁就容易导致其他线程卡死。monitor会去监控等待锁的时长,如果超过某个阈值(正常是100ms,调试模式下是1s)就会输出上面的Long monitor contention打印提醒我们:
// https://cs.android.com/android/platform/superproject/+/android-9.0.0_r60:art/runtime/monitor.cc
static constexpr uint64_t kDebugThresholdFudgeFactor = kIsDebugBuild ? 10 : 1;
static constexpr uint64_t kLongWaitMs = 100 * kDebugThresholdFudgeFactor;
...
} else if (wait_ms > kLongWaitMs && owners_method != nullptr) {
uint32_t pc;
ArtMethod* m = self->GetCurrentMethod(&pc);
// TODO: We should maybe check that original_owner is still a live thread.
LOG(WARNING) << "Long "
<< PrettyContentionInfo(original_owner_name,
original_owner_tid,
owners_method,
owners_dex_pc,
num_waiters)
<< " in " << ArtMethod::PrettyMethod(m) << " for "
<< PrettyDuration(MsToNs(wait_ms));
}
...
例如下面的代码sleep1会卡住sleep2:
private void testLongMonitor() {
new Thread("TestLongMonitor1") {
@Override
public void run() {
super.run();
sleep1();
}
}.start();
new Thread("TestLongMonitor2") {
@Override
public void run() {
super.run();
sleep2();
}
}.start();
}
private synchronized void sleep1() {
try {
Thread.sleep(1000);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
private synchronized void sleep2() {
try {
Thread.sleep(1000);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
在进入sleep2的时候就能看到下面的打印:
Long monitor contention with owner TestLongMonitor1 (3457) at void me.linjw.demo.MainActivity.sleep1()(MainActivity.java:41) waiters=0 in void me.linjw.demo.MainActivity.sleep2() for 1s
所以当我们看到这个打印的时候就应该去检查下是否在上锁的代码块里面做了耗时操作。
kill -3 命令
再来看看这个日志:
Long monitor contention with owner MQTT Call: LinJwDemoMqtt_1672223154916 (1252) at void java.lang.Thread.sleep(java.lang.Object, long, int)(Thread.java:-2) waiters=0 in java.util.List d.d.e.c.k.b.f.f(java.lang.String, java.lang.String) for 270.749s
让我比较难以理解的是LinJwDemoMqtt_1672223154916这个线程是卡在了java.lang.Thread.sleep这里。难道说我们的代码里面会有一个sleep 270秒的操作?搜索完整个代码都没有找到sleep的调用,于是只能压测复现然后使用"kill -3 {pid}"命令强制打印出进程的堆栈,然后在/data/anr/目录下找到它:
"MQTT Call: LinJwDemoMqtt_1672223154916" prio=5 tid=21 Sleeping
| group="main" sCount=1 dsCount=0 flags=1 obj=0x132c06f0 self=0x7d42a40800
| sysTid=1561 nice=0 cgrp=default sched=0/0 handle=0x7d329144f0
| state=S schedstat=( 2172565480 1496095545 17833 ) utm=151 stm=64 core=5 HZ=100
| stack=0x7d32811000-0x7d32813000 stackSize=1041KB
| held mutexes=
at java.lang.Thread.sleep(Native method)
- sleeping on <0x07054ef1> (a java.lang.Object)
at java.lang.Thread.sleep(Thread.java:373)
- locked <0x07054ef1> (a java.lang.Object)
at java.lang.Thread.sleep(Thread.java:314)
at android.net.LocalSocketImpl$SocketOutputStream.flush(LocalSocketImpl.java:185)
at d.d.e.b.c.b.a(:2)
at d.d.e.c.k.b.f.g(:-1)
at d.d.e.c.k.b.f.f(:-1)
- locked <0x0ab63ad6> (a d.d.e.c.k.b.f)
at d.d.e.c.k.b.e.a(:-1)
at d.d.e.c.k.a.a(:2)
at d.d.e.c.j.d$a.a(:3)
at d.d.e.c.h.e$a.a(:30)
at g.b.a.a.a.l.c.d(:12)
at g.b.a.a.a.l.c.run(:-1)
at java.lang.Thread.run(Thread.java:764)
发现是卡在了LocalSocket里面,我们的确会使用localsocket做通讯。翻看LocalSocketImpl的源码会找到这样一个丑陋的实现:
// https://cs.android.com/android/platform/superproject/+/android-9.0.0_r60:frameworks/base/core/java/android/net/LocalSocketImpl.java
public void flush() throws IOException {
FileDescriptor myFd = fd;
if (myFd == null) throw new IOException("socket closed");
// Loop until the output buffer is empty.
Int32Ref pending = new Int32Ref(0);
while (true) {
try {
// See linux/net/unix/af_unix.c
Os.ioctlInt(myFd, OsConstants.TIOCOUTQ, pending);
} catch (ErrnoException e) {
throw e.rethrowAsIOException();
}
if (pending.value <= 0) {
// The output buffer is empty.
break;
}
try {
Thread.sleep(10);
} catch (InterruptedException ie) {
break;
}
}
}
有个while true里面去sleep了10ms。但是这里和我们看到的270多秒相差甚远,就算Thread.sleep再怎么有误差也差不了这么多。
由于是开机的时候出现的,考虑可能是时间同步的锅,可能在sleep前后系统时间改变了。但是翻看日志发现时间是连续的没有出现跳变。
schedstat
我连续抓了几次堆栈,发现schedstat值是在增加的:
// 第一次抓取
"MQTT Call: LinJwDemoMqtt_1672223154916" prio=5 tid=21 Sleeping
| group="main" sCount=1 dsCount=0 flags=1 obj=0x132c06f0 self=0x7d42a40800
| sysTid=1561 nice=0 cgrp=default sched=0/0 handle=0x7d329144f0
| state=S schedstat=( 1808090884 1440374635 15039 ) utm=129 stm=50 core=4 HZ=100
// 第二次抓取
"MQTT Call: LinJwDemoMqtt_1672223154916" prio=5 tid=21 Sleeping
| group="main" sCount=1 dsCount=0 flags=1 obj=0x132c06f0 self=0x7d42a40800
| sysTid=1561 nice=0 cgrp=default sched=0/0 handle=0x7d329144f0
| state=S schedstat=( 2391421933 1559350961 20051 ) utm=165 stm=73 core=3 HZ=100
// 第三次抓取
"MQTT Call: LinJwDemoMqtt_1672223154916" prio=5 tid=21 Sleeping
| group="main" sCount=1 dsCount=0 flags=1 obj=0x132c06f0 self=0x7d42a40800
| sysTid=1561 nice=0 cgrp=default sched=0/0 handle=0x7d329144f0
| state=S schedstat=( 3049001564 1709661634 25792 ) utm=210 stm=94 core=1 HZ=100
这个schedstat其实是Linux里面的东西,从文档来看这三个值分别是:
- 在cpu上花费的时间（纳秒）
- 等待运行队列所花费的时间（纳秒）
- 此cpu上运行的时间片数
我们也可以用cat命令直接读取到:
cat /proc/{pic}/task/{tid}/schedstat
从schedstat来看线程占用的cpu时间片是一直在增加的,所以这个线程并不是一直sleep的。只能说读取owners_method的时候刚好抓到sleep这个方法了。
由于我们写入的数据是一个很短的字符串,于是结合LocalSocketImpl的源码可以猜测是Os.ioctlInt写入之后pending.value一直大于0。也许是localsocket接收端有问题,又有可能是系统本身在开机的时候某些状态有问题。
由于复现了几次,时间都是270、280秒,感觉系统本身的问题概率不大。于是写了个简单的测试接收端,发现只要接收端一直不去read数据,发送端flush里的while循环就一直出不来。
由于我们提供的客户端sdk里面使用okhttp封装了一层localsocket,okhttp的复用连接池里面socket的生存时间是5分钟,在生存时间到了之后就会自动回收socket,触发发送端的flush退出while循环。所以复现的几次都是卡了270、280多秒接近5分钟。从恢复时间点附近也找到了这样的日志作为佐证:
12-28 18:30:59.832 1852 2770 W System : A resource failed to call response.body().close().
线程锁定位
从上面我们只能看到其中的一个线程被localsocket堵住了,但是为什么mqtt会不断断开呢,我们从堆栈里面看到这个线程锁了一个0x0ab63ad6对象,在堆栈里搜索它,可以看到后面新启动的mqtt线程都在"waiting to lock <0x0ab63ad6> (a d.d.e.c.k.b.f) held by thread 21":
"MQTT Call: LinJwDemoMqtt_1672223188697" prio=5 tid=41 Blocked
| group="main" sCount=1 dsCount=0 flags=1 obj=0x13780ef8 self=0x7d42a3fc00
| sysTid=4307 nice=0 cgrp=default sched=0/0 handle=0x7d30f194f0
| state=S schedstat=( 9329835 2060251 4 ) utm=0 stm=0 core=2 HZ=100
| stack=0x7d30e16000-0x7d30e18000 stackSize=1041KB
| held mutexes=
at d.d.e.c.k.b.f.f(:-1)
- waiting to lock <0x0ab63ad6> (a d.d.e.c.k.b.f) held by thread 21
at d.d.e.c.k.b.e.a(:-1)
at d.d.e.c.k.a.a(:2)
at d.d.e.c.a.a(:3)
at d.d.e.c.j.d.a(:24)
at d.d.e.c.j.b.a(:1)
at d.d.e.c.h.e$a.a(:11)
at g.b.a.a.a.l.c.d(:12)
at g.b.a.a.a.l.c.run(:-1)
at java.lang.Thread.run(Thread.java:764)
"MQTT Call: LinJwDemoMqtt_1672223201187" prio=5 tid=42 Blocked
| group="main" sCount=1 dsCount=0 flags=1 obj=0x131c10b8 self=0x7d44472000
| sysTid=4730 nice=0 cgrp=default sched=0/0 handle=0x7d30e134f0
| state=S schedstat=( 23179915 15908085 274 ) utm=1 stm=0 core=3 HZ=100
| stack=0x7d30d10000-0x7d30d12000 stackSize=1041KB
| held mutexes=
at d.d.e.c.k.b.f.f(:-1)
- waiting to lock <0x0ab63ad6> (a d.d.e.c.k.b.f) held by thread 21
at d.d.e.c.k.b.e.a(:-1)
at d.d.e.c.k.a.a(:2)
at d.d.e.c.a.a(:3)
at d.d.e.c.j.d.a(:24)
at d.d.e.c.j.b.a(:1)
at d.d.e.c.h.e$a.a(:11)
at g.b.a.a.a.l.c.d(:12)
at g.b.a.a.a.l.c.run(:-1)
at java.lang.Thread.run(Thread.java:764)
"MQTT Call: LinJwDemoMqtt_1672223216180" prio=5 tid=43 Blocked
| group="main" sCount=1 dsCount=0 flags=1 obj=0x13782748 self=0x7d44472c00
| sysTid=4945 nice=0 cgrp=default sched=0/0 handle=0x7d30d0d4f0
| state=S schedstat=( 9939123 3184420 14 ) utm=0 stm=0 core=3 HZ=100
| stack=0x7d30c0a000-0x7d30c0c000 stackSize=1041KB
| held mutexes=
at d.d.e.c.k.b.f.f(:-1)
- waiting to lock <0x0ab63ad6> (a d.d.e.c.k.b.f) held by thread 21
at d.d.e.c.k.b.e.a(:-1)
at d.d.e.c.k.a.a(:2)
at d.d.e.c.a.a(:3)
at d.d.e.c.j.d.a(:24)
at d.d.e.c.j.b.a(:1)
at d.d.e.c.h.e$a.a(:11)
at g.b.a.a.a.l.c.d(:12)
at g.b.a.a.a.l.c.run(:-1)
at java.lang.Thread.run(Thread.java:764)
...
tid=21就是我们之前那个卡在flush的线程。
也就是说mqtt连接成功之后都会调用到localsocket的写入,写入之前我们的代码里面对代码块进行加锁,然后就都在等第一个线程的flush退出while循环,导致mqtt库接收不到broker的响应自动断开。
所以现在已经可以定位是提供的sdk的问题,接下来就需要处理sdk里面没有读取的异常情况。
