记一次文件fd耗尽排查过程

2,233 阅读7分钟

最近在排查项目中文件fd泄漏经历了非常曲折的过程,并且没有查到与我们业务遇到问题相关的文章,故记录下给后来者遇到类似问题提供一种思路。

1. 问题表现

首先最初看到这个下图这个堆栈以为是内存不够用了。 image.png 但是我们看上报的log可以发现,绝大部分机型似乎又有too many files open 这样的log提示。并且所有出问题的机型基本集中在8.1以下。通过搜索得知这样一个事实:在8.1以下的设备文件fd是存在数量限制。在9.0之后这个限制被极大放宽。 image.png 于是可以确定这个问题与文件fd相关。

2. android中文件fd初步排查

此时虽然知道是文件泄漏,但是不清楚到底是什么导致了文件fd泄漏,于是一开始猜测是否cursor存在使用了未关情况。

2.1 是否为资源泄漏?

如何运行时检测是否存在cursor未关闭呢?

好在前人已经帮我们种好了树。Matrix 有个IO Canary 插件,它能检测文件 IO 问题。包括:文件IO监控和Closeable Leak监控。Cursor 实现了Closeable接口自然也在监控范围内。
按照预期日志平台收集到的close leak 堆栈应该有很多条,但是实际上崩溃时收集到的日志只有有限几条。

image.png 通过IO Canary Plugin上报的日志可以让我们确认 fd泄漏似乎与Cursor 未关闭无关。但是根据当前现有的知识量线索似乎到此中断。

2.2 文件fd类型探究

但是天无绝人之路,由于之前接触过KOOM知道它有个FdOOMTracker,它能读取当前应用所有打开的文件。核心源码如下:

private fun dumpFdIfNeed() {
  MonitorLog.i(TAG, "over threshold dumpFdIfNeed")

  if (mOverThresholdCount > monitorConfig.maxOverThresholdCount) return

  if (Build.VERSION.SDK_INT < Build.VERSION_CODES.LOLLIPOP) return

  val fdNames = runCatching { File("/proc/self/fd").listFiles() }
      .getOrElse {
        MonitorLog.i(TAG, "/proc/self/fd child files is empty")

        return@getOrElse emptyArray()
      }
      ?.map { file ->
        runCatching { Os.readlink(file.path) }.getOrElse { "failed to read link ${file.path}" }
      }
      ?: emptyList()

  OOMFileManager.createDumpFile(OOMFileManager.fdDumpDir)
      .run {
        runCatching { writeText(fdNames.sorted().joinToString(separator = ",")) }
      }
}

于是将上述代码稍加改造,在fd数目达到阈值的80%上报当前所有打开的文件路径以及崩溃的时候再上报一次。最终得到线上出问题的文件fd分布如下:

image.png

通过上图可知我们app文件消耗大户为pipe类型、以及socket类型。
根据vivo技术团队的分享可知各种文件fd作用如下:

image.png
pipe类型似乎与Looper有关系,这其实也在一定程度上误导了我。Looper阻塞的实现其实根据版本不同实现不同:

  • 在Android 6.0及以前的版本使用管道与epoll来完成Looper的休眠与唤醒的。
  • 在Android 6.0及以后的新版本中使用的是eventfd与epoll来完成Looper的休眠与唤醒的。

但是我们应用7.0-8.0的pipe fd过多导致的cursor创建失败崩溃依旧很多,所以应该和Looper没有关系。线索到这里似乎又断了,因为不太能确定项目中是谁在创建pipe类型fd。

3. 利用matrix hook 定位问题过程

因为找不到问题的源头,于是我想是不是可以通过其他指标看看有无异常。在解决了项目中存在的明显内存泄漏,IO问题等一些其他性能问题后,在收敛线程池接触到了Matrix Hook中的PThread Hook插件。稍微研究了下它的实现,它给了我定位问题的新思路。PThread Hook 主要是基于xHook做的,hook pthread_create、pthread_detach,生成其调用堆栈。这样我们就能知道是谁创建了线程以及线程有无销毁。

3.1 PLTHook 介绍

PLT Hook 主要的的作用是替换某个so的外部函数调用,我们可以将其修改成我们自己的函数地址以实现某种目的。比如做性能监控、native问题诊断等。这种替换通常不需侵入原本代码实现,故而是一种非常强大的技术。
PLT Hook 具体的原理大致和ELF文件格式以及重定位其中的函数地址有关。具体可以看下方参考资料中[4] [5]介绍,这里先不过多展开。

3.2 Martix Hook 使用步骤

因为我觉得自己从头开始使用xhook不如直接使用Matrix Hook中的基础设施方便,所以PipeHook是在Matrix Hook上实现的。这样就得先谈谈我对Matrix Hook基础设施使用的理解。 Matrix Hook 用宏定义使用xHook的模版,它帮我们简化了使用步骤。这些模版代码位于common/HookCommon.h中。如果我们想用Matrix Hook hook自己想要的so具体步骤如下:

  1. 定义需要Hook的so 例如
#define ORIGINAL_LIB "libc.so"

请注意一定要使用ORIGINAL_LIB这个名称定义,因为HookCommon的宏中dlopen使用ORIGINAL_LIB这个名称获取handle。

#define CALL_ORIGIN_FUNC_RET(retType, ret, sym, params...) \
    if (!ORIGINAL_FUNC_NAME(sym)) { \
        void *handle = dlopen(ORIGINAL_LIB, RTLD_LAZY); \
        if (handle) { \
            ORIGINAL_FUNC_NAME(sym) = (FUNC_TYPE(sym))dlsym(handle, #sym); \
        } \
    } \
    retType ret = ORIGINAL_FUNC_NAME(sym)(params)
  1. 使用DECLARE_HOOK_ORIG宏保存被hook函数。它实现是定义一个与被Hook函数相同类型的函数指针类型的变量保存原函数的地址。第一个参数为Hook函数的返回类型,第二个参数为被hook函数名称,其余皆为被hook函数的参数类型。以hook pthread_create举例:
DECLARE_HOOK_ORIG(int, pthread_create, pthread_t*, pthread_attr_t const*, pthread_hook::pthread_routine_t, void*);
  1. 使用DEFINE_HOOK_FUN宏定义被Hook函数。Hook函数中调用原函数的方式为使用宏CALL_ORIGIN_FUNC_RET
DEFINE_HOOK_FUN(int, pthread_detach, pthread_t pthread) {
    CALL_ORIGIN_FUNC_RET(int, ret, pthread_detach, pthread);
    LOGD(LOG_TAG, "pthread_detach : %d", ret);
    if (LIKELY(ret == 0) && sThreadTraceEnabled) {
        thread_trace::handle_pthread_release(pthread);
    }
    return ret;
}
  1. 按照下述代码Hook libc相关函数
// 获取被hook函数的函数地址并存在 orig_##fn_name变量中(在编译时这个变量会被展开成实际函数名称e.g. orig_ptherad_create)
FETCH_ORIGIN_FUNC(pthread_create)

// 暂停so加载
matrix::PauseLoadSo();
xhook_block_refresh();
{
    // 将system symbol 中被hook函数替换成 h_##fn_name实现
    int ret = xhook_export_symtable_hook("libc.so", "pthread_create",
                                         (void *) HANDLER_FUNC_NAME(pthread_create), nullptr);
    LOGD(LOG_TAG, "export table hook sym: pthread_create, ret: %d", ret);

    // 加入到hook列表中,最终将应用中加载的so中的被hook函数 转换为hook函数
    xhook_grouped_register(HOOK_REQUEST_GROUPID_PTHREAD, ".*/.*\.so$", "pthread_create",
                           (void *) HANDLER_FUNC_NAME(pthread_create), nullptr);

    xhook_enable_debug(enable_debug ? 1 : 0);
    xhook_enable_sigsegv_protection(0);
    xhook_refresh(0);
}
xhook_unblock_refresh();
// 恢复so加载
matrix::ResumeLoadSo();

  1. 在宏NOTIFY_COMMON_IGNORE_LIBS中添加自己实现hook逻辑so的名称,以排除掉对自身的实现中调用了被hook函数又被hook,避免套娃。
#define NOTIFY_COMMON_IGNORE_LIBS(group_id) \
    do { \
      xhook_grouped_ignore(group_id, ".*/libmatrix-hookcommon\.so$", NULL); \
      xhook_grouped_ignore(group_id, ".*/libmatrix-memoryhook\.so$", NULL); \
      xhook_grouped_ignore(group_id, ".*/libmatrix-pthreadhook\.so$", NULL); \
NULL); \
    } while (0)

其实如果不是hook像系统的libc之类的动态库完全没必要使用这一套。

3.3 PipeHook设计思路

我们之前最大的问题是不确定谁使用了pipe类型文件fd。PipeHook主要的目的也是在于定位那处代码创建了pipe fd以及创建的pipe有无销毁。
首先根据handler6.0 阻塞实现可知,pipe类型的描述符主要是posix函数pipe pipe2函数创建:

int fd[2];
result = pipe(fd);//创建一个管道
if (result == -1) {
    exit(EXIT_FAILURE);
}

close(fd[1]);

关闭时用到了posix函数 close。 那么PipeHook的只需要hook pipe() pipe2() 以及close()函数即可达成我们的目标。比较令人高兴是这些函数都在libc.so中。至于hook 其他方法如果不确定可以读取app应用加载的so,然后在root手机pull出相应的so使用下面命令查找。
nm -D libName.so | grep symbolName

下面给出PipeHook Hook的实现代码:

#define LOG_TAG "Matrix.PipeHook"
#define ORIGINAL_LIB "libc.so"

static volatile bool sPipeTraceEnabled = false;

DECLARE_HOOK_ORIG(int, pipe, int[]);

DECLARE_HOOK_ORIG(int, pipe2, int[], int);

DECLARE_HOOK_ORIG(int, close, int);

DEFINE_HOOK_FUN(int, pipe, int fds[]) {
    CALL_ORIGIN_FUNC_RET(int, ret, pipe, fds);
    LOGD(LOG_TAG, "hook pipe return: %d create pipe([%d %d])", ret, fds[0], fds[1]);
    if (LIKELY(ret == 0) && sPipeTraceEnabled){
        pipe_hook_trace::handle_invoke_pipe(fds,pipe_func_type);
    }
    return ret;
}

DEFINE_HOOK_FUN(int, pipe2, int fds[], int flags) {
    CALL_ORIGIN_FUNC_RET(int, ret, pipe2, fds, flags);
    LOGD(LOG_TAG, "hook pipe2([%d,%d],%d) return: %d", fds[0], fds[1], flags, ret);
    if (LIKELY(ret == 0) && sPipeTraceEnabled){
        pipe_hook_trace::handle_invoke_pipe(fds,pipe2_func_type);
    }
    return ret;
}

DEFINE_HOOK_FUN(int, close, int fd) {
    CALL_ORIGIN_FUNC_RET(int, ret, close, fd);
//    LOGD(LOG_TAG, "hook close return: %d close(%d)", ret, fd);
    if (LIKELY(ret == 0)){
        pipe_hook_trace::handle_invoke_close(fd);
    }
    return ret;
}

namespace pipe_usage_hook {
    void SetPipeTraceEnabled(bool enabled) {
        sPipeTraceEnabled = enabled;
    }

    void InstallPipeHooks(bool enable_debug) {
        LOGI(LOG_TAG, "[+] Calling InstallHooks, sPipeTraceEnabled: %d", sPipeTraceEnabled);

        if (!sPipeTraceEnabled) {
            LOGD(LOG_TAG, "[*] InstallPipeHooks was ignored.");
            return;
        }

        FETCH_ORIGIN_FUNC(pipe);
        FETCH_ORIGIN_FUNC(pipe2);

        FETCH_ORIGIN_FUNC(close);

        matrix::PauseLoadSo();
        xhook_block_refresh();
        {
            int ret = xhook_export_symtable_hook("libc.so", "pipe",
                                                 (void *) HANDLER_FUNC_NAME(pipe), nullptr);
            LOGD(LOG_TAG, "export table hook sym: pipe, ret: %d", ret);

            ret = xhook_export_symtable_hook("libc.so", "pipe2",
                                             (void *) HANDLER_FUNC_NAME(pipe2), nullptr);
            LOGD(LOG_TAG, "export table hook sym: pipe2, ret: %d", ret);


            ret = xhook_export_symtable_hook("libc.so", "close",
                                             (void *) HANDLER_FUNC_NAME(close), nullptr);
            LOGD(LOG_TAG, "export table hook sym: close, ret: %d", ret);

            xhook_grouped_register(HOOK_REQUEST_GROUPID_PIPE, ".*/.*\.so$", "pipe",
                                   (void *) HANDLER_FUNC_NAME(pipe), nullptr);
            xhook_grouped_register(HOOK_REQUEST_GROUPID_PIPE, ".*/.*\.so$", "pipe2",
                                   (void *) HANDLER_FUNC_NAME(pipe2), nullptr);
            xhook_grouped_register(HOOK_REQUEST_GROUPID_PIPE, ".*/.*\.so$", "close",
                                   (void *) HANDLER_FUNC_NAME(close), nullptr);

            xhook_enable_debug(enable_debug ? 1 : 0);
            xhook_enable_sigsegv_protection(0);
            xhook_refresh(0);
        }
        xhook_unblock_refresh();
        matrix::ResumeLoadSo();
    }
}

3.4 PipeHook定位到的问题

收集到的处于打开状态的pipe类型fd如下(因为Matrix堆栈聚合同时考虑java和native hash导致比较分散,仅截部分图说明)

image.png java部分堆栈:

org.conscrypt.NativeCrypto.SSL_new(Native Method);
org.conscrypt.NativeSsl.newInstance(NativeSsl.java:79);
org.conscrypt.ConscryptFileDescriptorSocket.newSsl(ConscryptFileDescriptorSocket.java:171);
org.conscrypt.ConscryptFileDescriptorSocket.<init>(ConscryptFileDescriptorSocket.java:165);
org.conscrypt.Java8FileDescriptorSocket.<init>(Java8FileDescriptorSocket.java:61);
org.conscrypt.Platform.createFileDescriptorSocket(Platform.java:660);
org.conscrypt.OpenSSLSocketFactoryImpl.createSocket(OpenSSLSocketFactoryImpl.java:152);
okhttp3.internal.connection.RealConnection.connectTls(RealConnection.kt:369);
okhttp3.internal.connection.RealConnection.establishProtocol(RealConnection.kt:337);
okhttp3.internal.connection.RealConnection.connect(RealConnection.kt:209);
okhttp3.internal.connection.ExchangeFinder.findConnection(ExchangeFinder.kt:226);

native部分堆栈:


#pc 8bbb8 (null) (/data/app/fm.qingting.qtradio-53nKzoRu3fsqGrWE9F_a2Q==/lib/arm64/libconscrypt_jni.so);
#pc 7cd04 (null) (/data/app/fm.qingting.qtradio-53nKzoRu3fsqGrWE9F_a2Q==/lib/arm64/libconscrypt_jni.so);
#pc 156744 (null) (/data/app/fm.qingting.qtradio-53nKzoRu3fsqGrWE9F_a2Q==/oat/arm64/base.odex);
#pc b40b4 art::ArtMethod::Invoke(art::Thread*, unsigned int*, unsigned int, art::JValue*, char const*) (/system/lib64/libart.so);
#pc 25e1e0 art::interpreter::ArtInterpreterToCompiledCodeBridge(art::Thread*, art::ArtMethod*, art::DexFile::CodeItem const*, art::ShadowFrame*, art::JValue*) (/system/lib64/libart.so);
#pc 2588a8 bool art::interpreter::DoCall<false, false>(art::ArtMethod*, art::Thread*, art::ShadowFrame&, art::Instruction const*, unsigned short, art::JValue*) (/system/lib64/libart.so);
#pc 4ce134 (null) (/system/lib64/libart.so);
#pc 4d6e94 (null) (/system/lib64/libart.so);
#pc 239624 (null) (/system/lib64/libart.so);
#pc 23fd24 art::interpreter::ArtInterpreterToInterpreterBridge(art::Thread*, art::DexFile::CodeItem const*, art::ShadowFrame*, art::JValue*) (/system/lib64/libart.so);
#pc 258888 bool art::interpreter::DoCall<false, false>(art::ArtMethod*, art::Thread*, art::ShadowFrame&, art::Instruction const*, unsigned short, art::JValue*) (/system/lib64/libart.so);

通过上述可以看出这个是okhttp中建立https连接,ssl握手实现大量使用了pipe类型fd。通过堆栈按图索骥发现了这样的代码:

// There is a thread leak related to HttpUrlConnection on some devices.
if (Build.VERSION.SDK_INT in Build.VERSION_CODES.M..Build.VERSION_CODES.O) {
    Security.insertProviderAt(Conscrypt.newProvider(), 1)
    URL.setURLStreamHandlerFactory(ObsoleteUrlFactory(DefaultHttpClient.client))
}

这段代码意思是替换使用Google的conscrypt库代替ssl层握手加密实现,同时将项目中的HttpUrlConnection替换成自己okhttp实现。这段代码嫌疑最大,于是我们对这段代码进行了ab控制,在实验组cursor创建不了的问题基本不在复现并且注释提到问题并没有显著的对其他指标造成影响。至此我们可以说已经解决了这个崩溃。
但是团队中的其他小伙伴提出其实android 内置的加解密库也是conscrypt。于是也看看对照组pipe 创建情况:

image.png

同样的java堆栈对应的native调用堆栈:

#pc 2c964 (null) (/system/lib64/libjavacrypto.so);#pc 1dcfc (null) (/system/lib64/libjavacrypto.so);
#pc 2bc78 (null) (/system/framework/arm64/boot-conscrypt.oat);
#pc b40b4 art::ArtMethod::Invoke(art::Thread*, unsigned int*, unsigned int, art::JValue*, char const*) (/system/lib64/libart.so);
#pc 25e1e0 art::interpreter::ArtInterpreterToCompiledCodeBridge(art::Thread*, art::ArtMethod*, art::DexFile::CodeItem const*, art::ShadowFrame*, art::JValue*) (/system/lib64/libart.so);
#pc 2588a8 bool art::interpreter::DoCall<false, false>(art::ArtMethod*, art::Thread*, art::ShadowFrame&, art::Instruction const*, unsigned short, art::JValue*) (/system/lib64/libart.so);
#pc 4ce134 (null) (/system/lib64/libart.so);
#pc 4d6e94 (null) (/system/lib64/libart.so);
#pc 239624 (null) (/system/lib64/libart.so);
#pc 23fd24 art::interpreter::ArtInterpreterToInterpreterBridge(art::Thread*, art::DexFile::CodeItem const*, art::ShadowFrame*, art::JValue*) (/system/lib64/libart.so);#pc 258888 bool art::interpreter::DoCall<false, false>(art::ArtMethod*, art::Thread*, art::ShadowFrame&, art::Instruction const*, unsigned short, art::JValue*) (/system/lib64/libart.so);

可以发现内置的libjavacrypto实现似乎比libconscrypt_jni创建pipe fd数量少一点。这也能解释为啥切换到默认实现能work的缘由。
以上对比只是选取了各自创建pipe 类型fd最多的堆栈对比可能不是非常严谨,但是足以说明问题。 到这里基本可以结案了,但是我们只是找到了直接原因而非根本原因。现在有两个怀疑方向:

  1. app存在connection泄漏导致pipe类型fd无法释放?
  2. 同一时间网络请求太多导致触达fd 文件数目上限?

4. 网络请求的进一步探究

要搞清楚到底是connection中的socket没有关闭还是单纯网络请求需要创建的fd超过了系统上限,那我们需要从connection中socket创建以及socket销毁时间点入手。
查看okhttp源码可以发现socket创建是在ExchangeFinder.findConnection中完成:

@Throws(IOException::class)
private fun findConnection(
  connectTimeout: Int,
  readTimeout: Int,
  writeTimeout: Int,
  pingIntervalMillis: Int,
  connectionRetryEnabled: Boolean
): RealConnection {
  if (call.isCanceled()) throw IOException("Canceled")

  // Attempt to reuse the connection from the call.
   xxx逻辑

  // Attempt to get a connection from the pool.
   xxx逻辑

  // Nothing in the pool. Figure out what route we'll try next.
   xxx逻辑

  // Connect. Tell the call about the connecting call so async cancels work.
  val newConnection = RealConnection(connectionPool, route)
  call.connectionToCancel = newConnection
  try {
    newConnection.connect(
        connectTimeout,
        readTimeout,
        writeTimeout,
        pingIntervalMillis,
        connectionRetryEnabled,
        call,
        eventListener
    )
  } finally {
    call.connectionToCancel = null
  }
  call.client.routeDatabase.connected(newConnection.route())

  // If we raced another call connecting to this host, coalesce the connections. This makes for 3
  // different lookups in the connection pool!
    xxx逻辑
    
  synchronized(newConnection) {
    connectionPool.put(newConnection)
    call.acquireConnectionNoEvents(newConnection)
  }
  return newConnection
}

具体okhttp复用连接逻辑可以看参考文章[7]。
那么可以把connection.put 认为是一个socket 被创建出来的标志。于是我们可以是aspectjx写出如下hook代码:

    @Before("execution(* okhttp3.internal.connection.RealConnectionPool.put(..))")
    public void onPutConnectionToPool(JoinPoint joinPoint) {
        if (!(joinPoint.getThis() instanceof RealConnectionPool)) {
            return;
        }

        RealConnectionPool pool = (RealConnectionPool) joinPoint.getThis();
        ConnectionLeakWatcher.INSTANCE.recordConnectionPool(pool);

        if (joinPoint.getArgs() == null || joinPoint.getArgs().length < 1 || !(joinPoint.getArgs()[0] instanceof RealConnection)) {
            return;
        }
        RealConnection connection = (RealConnection) joinPoint.getArgs()[0];
        ConnectionLeakWatcher.INSTANCE.recordCreatedConnectionRequest(connection, pool);
    }

而socket关闭路径比较多大概有:

  • 连接池定时清理最大空闲连接
  • 当前socket连接没有更多网络请求
  • 重试发现socket连接不能复用关闭
  • 异常关闭

经过寻找发现两处可以认为是socket关闭的点:

  1. Closeable.closeQuietly()
  2. RealConnection.socket()

最后我选择RealConnection.socket()作为hook点,因为RealConnection拿到的上下文数据更多方便socket与url建立对应关系:

@Before("execution(* okhttp3.internal.connection.RealConnection.socket())")
public void onGetSocketToClose(JoinPoint joinPoint) {
    LogcatUtil.d(joinPoint.getKind());

    RealConnection conn = (RealConnection) joinPoint.getThis();
    ConnectionLeakWatcher.INSTANCE.recordConnReleased(conn);
}

根据崩溃用户的行为路径构造出case:将app冷启动然后将首页所有tab点一遍(一共加起来花了30s)最后静置3min作为测试场景。最后将收集到的数据过滤出所有未关闭的socket:

image.png 通过上述实验数据可以发现:我们app发送网络请求非常频繁,并且这些连接基本都被关闭不存在泄漏问题。 至此导致cursor的最终问题可以确认了:

过于频繁的网络请求 + 使用conscrypt库替代系统ssl握手中加密实现 导致了cursor创建失败的crash。

5. 最后

在排查这个cursor创建失败的crash我们接触到了xhook matrix aspectjx工具,学会并理解他们的内部工作原理往往会对解决疑难问题有奇效。

参考资料
[1]Matrix for Android
[2]一文帮你搞懂 Android 文件描述符
[3]Android Handler 机制(三):Handler 机制与管道 Pipe 机制
[4] PLT HooK
[5] android中基于plt/got的hook实现原理
[6] 不可思议的OOM
[7]OkHttp 原理 8 连问