记一个App卡死问题的解决过程

问题布景：

先介绍下项目，我做的是一个摄像头的App，一起有多个线程在处理接纳数据、解码、烘托等逻辑，并且调试进程中打了许多日志。 之前使用的是NSLogger来记载并传输log到mac 端展示，但后边发现这个框架有些问题，常常存在连不上的问题，并且网络故障时，日志全都丢掉了。因而后边改成了用dup2重定向stderr和stdout到指定管道的方法把日志悉数写到本地。这个计划一开始没有什么问题，但随着日志越来越多， 在播映进程中就常常会呈现卡死的现象，点击屏幕任何方位都没有反响，卡死时CPU使用率为0。导出日志也发现不了什么问题。

处理进程：

首先，从CPU的使用率上来看，应该不是死循环或许是什么耗时任务导致的卡死，比较像是死锁导致的，那么怎么排查死锁问题呢？ 我在网上找到了一个文章/post/703745…

这里思路便是独自拓荒一个线程，每隔3秒钟去dump所有的线程，并逐个查看其cpu使用率和运行状态，如果cpu使用率大于80%且为运行中就大概率是死循环了，如果是cpu使用率为0，并且栈顶指令是__psynch_mutexwait ，则是死锁。

通过这种方法证清晰实是死锁了，调用栈如下：

从调用栈能够看出是printf和debugPrint导致的，这两个函数都是打印日志的，因而我判定是写日志引发的。但问题来了，为啥在控制台打印日志的时分没问题，写到本地却有问题呢？

关于这个问题，我没有找到清晰的答案，可是大致能够揣度是由于把日志写到本地文件时，体系为了防止多线程竞赛导致脏数据而选用了加锁的方法，而打印到控制台则不存在这个问题。

并且像NSLogger也是选用dup2的方法去重定向日志，却没有产生卡死，问题是在哪呢？

问题出在哪里？

带着这个疑问，我试着注释掉部分代码来排查问题。最开始我是这样写的：

- (void)redirectNotificationHandle:(NSNotification *)nf{
    NSData *data = [[nf userInfo] objectForKey:NSFileHandleNotificationDataItem];
    NSString *output = [[NSString alloc] initWithData:data encoding:NSUTF8StringEncoding];
    [self saveLogMessage:output];
    [[nf object] readInBackgroundAndNotify];
}
//这个方法当多个线程一起写日志时会造成死锁，不引荐使用
- (void)redirectSTD:(int )fd{
    NSPipe * pipe = [NSPipe pipe] ;
    NSFileHandle *pipeReadHandle = [pipe fileHandleForReading] ;
    dup2([[pipe fileHandleForWriting] fileDescriptor], fd) ;
    // 翻开文件
    NSString *documentpath = [NSSearchPathForDirectoriesInDomains(NSDocumentDirectory, NSUserDomainMask, YES) lastObject];
    NSString *logDir = [documentpath stringByAppendingFormat:@"/logs"];
    NSString *fileName = [NSString stringWithFormat:@"printf_%@.log",[NSDate date]];
    NSString *logFilePath = [logDir stringByAppendingPathComponent:fileName];
    NSFileHandle *fileHandle = [NSFileHandle fileHandleForWritingAtPath:logFilePath];
    if (fileHandle == nil) {
        [[NSFileManager defaultManager] createFileAtPath:logFilePath contents:nil attributes:nil];
        fileHandle = [NSFileHandle fileHandleForWritingAtPath:logFilePath];
    }
    self.fileHandle = fileHandle;
    [[NSNotificationCenter defaultCenter] addObserver:self selector:@selector(redirectNotificationHandle:) name:NSFileHandleReadCompletionNotification object:pipeReadHandle] ;
    [pipeReadHandle readInBackgroundAndNotify];
}
- (void)saveLogMessage:(NSString *)message {
    if (!self.dateFormatter) {
        self.dateFormatter = [[NSDateFormatter alloc] init];
        [self.dateFormatter setDateFormat:@"yyyy-MM-dd HH:mm:ss.SSS"];
    }
    NSFileHandle* fileHandler = self.fileHandler;    
    NSString *currentTime = [self.dateFormatter stringFromDate:[NSDate date]];
    if (message.length > 0) {
        NSArray *lines = [message componentsSeparatedByString:@"\n"];
        for (NSString *line in lines) {
            NSString *newLine = [NSString stringWithFormat:@"%@ %@", currentTime, line];
            [fileHandler writeData:[newLine dataUsingEncoding:NSUTF8StringEncoding]];
            [fileHandler writeData:[@"\n" dataUsingEncoding:NSUTF8StringEncoding]];
        }
    }
}

我测验把saveLogMessage这个函数的内容给注释掉，发现仍是会卡死，因而问题不在写文件这里。然后我再注释掉redirectNotificationHandle 这个函数里边的所有代码，呈现了溃散，原因是readInBackgroundAndNotify 这句必需要调用。加上这一句之后没有溃散了，可是仍是会卡死。 然后我再把NSFileHandleReadCompletionNotification 添加监听的代码也注释了，这才没有卡死。因而能够判定问题出在NSFileHandleReadCompletionNotification 这个告诉的发送上。由于没有找到相关源码，我无法进一步的探求原因，但从表象来看，不论在哪个线程打日志，一定是在主线程接纳这个告诉，我估测应该是发送这个告诉时内部做了加锁来控制日志的次序。如果有熟悉这块的朋友，能够一起探讨下。

那怎么处理这个问题呢？

1. 最简略的方法便是关闭写日志到本地，但这样在排查问题时极为不方便，因而 pass了。

2. 减少日志，仅保留必要的日志，这个也无法从根本上处理卡死的问题，仍是会有概率产生，因而也pass了。

3. 不选用dup2重定向标准输出流，而是自己定义一些宏，来替代体系的NSlog和printf之类的函数，这个计划可行，也能从根本上防止重定向导致的卡死，但工作量偏大，不是最优解。

4. 看看NSlogger、cocoalumberjack之类的第三方库是怎么处理这个问题的，借鉴一下。

终究我是决议借鉴NSlogger， 由于这个库之前用了一段时间，没发现过卡死的现象，而cocoalumberjack无法捕获到printf的日志（网上说是能够，但我实践下来发现不可，可能是用法不对吧）。

在loggerClient.m里边我们能够看到他是怎么处理日志重定向的，这里只摘出核心代码剖析

static void LoggerStartConsoleRedirection()
{
	// protected by `consoleGrabbersMutex`
	// keep the original pipes so we can still forward everything
	// (i.e. to the running IDE that needs to display or interpret console messages)
	// and remember the SIGPIPE settings, as we are going to clear them to prevent
	// the app from exiting when we close the pipes
	if (sSTDOUT == -1)
	{
		sSTDOUThadSIGPIPE = fcntl(STDOUT_FILENO, F_GETNOSIGPIPE);
		sSTDOUT = dup(STDOUT_FILENO);
		sSTDERRhadSIGPIPE = fcntl(STDERR_FILENO, F_GETNOSIGPIPE);
		sSTDERR = dup(STDERR_FILENO);
	}
	// create the pipes
	if (sConsolePipes[0] == -1)
	{
		if (pipe(sConsolePipes) != -1)
		{
			fcntl(sConsolePipes[0], F_SETNOSIGPIPE, 1);
			fcntl(sConsolePipes[1], F_SETNOSIGPIPE, 1);
			dup2(sConsolePipes[1], STDOUT_FILENO);
		}
	}
	if (sConsolePipes[2] == -1)
	{
		if (pipe(&sConsolePipes[2]) != -1)
		{
			fcntl(sConsolePipes[0], F_SETNOSIGPIPE, 1);
			fcntl(sConsolePipes[1], F_SETNOSIGPIPE, 1);
			dup2(sConsolePipes[3], STDERR_FILENO);
		}
	}
	pthread_create(&consoleGrabThread, NULL, &LoggerConsoleGrabThread, NULL);
}
static void *LoggerConsoleGrabThread(void *context)
{
#pragma unused (context)
	pthread_mutex_lock(&consoleGrabbersMutex);
	int fdout = sConsolePipes[0];
	fcntl(fdout, F_SETFL, fcntl(fdout, F_GETFL, 0) | O_NONBLOCK);
	int fderr = sConsolePipes[2];
	fcntl(fderr, F_SETFL, fcntl(fderr, F_GETFL, 0) | O_NONBLOCK);
	CFMutableDataRef stdoutData = CFDataCreateMutable(NULL, 0);
	CFMutableDataRef stderrData = CFDataCreateMutable(NULL, 0);
	unsigned activeGrabbers = numActiveConsoleGrabbers;
	pthread_mutex_unlock(&consoleGrabbersMutex);
	while (activeGrabbers != 0)
	{
		fd_set set;
		FD_ZERO(&set);
		FD_SET(fdout, &set);
		FD_SET(fderr, &set);
		int ret = select(fderr + 1, &set, NULL, NULL, NULL);
		if (ret <= 0)
		{
			// ==0: time expired without activity
			// < 0: error occurred
			break;
		}
		pthread_mutex_lock(&consoleGrabbersMutex);
		activeGrabbers = numActiveConsoleGrabbers;
		if (activeGrabbers != 0)
		{
			if (FD_ISSET(fdout, &set))
				LoggerLogFromConsole(CFSTR("stdout"), fdout, sSTDOUT, stdoutData);
			if (FD_ISSET(fderr, &set ))
				LoggerLogFromConsole(CFSTR("stderr"), fderr, sSTDERR, stderrData);
		}
		pthread_mutex_unlock(&consoleGrabbersMutex);
	}
	CFRelease(stdoutData);
	CFRelease(stderrData);
	return NULL;
}

从NSLogger的源码能够看出，他也是使用了dup2进行重定向，仅仅前面加了fcntl 来防止捕获sigpipe的过错信号，另外便是拓荒了一个独自的线程，在这个线程里边使用while循环+select语句来守时轮询stderr和stdout文件描述符，如果有改变就从前面前面建立的管道里读出日志来。

模仿他的写法，我也实现了一个类似的方法，发现还的确不会卡死，并且读到的日志也是完好的。趁便提一嘴，他这里为了防止重定向影响到原有的控制台输出，还专门保留了之前的文件描述符，在后边处理日志的时分再次调用输出到控制台，详细代码就不贴了，感兴趣的能够去看下LoggerLogFromConsole这个函数的实现。

到这里，问题就基本处理了，可是为了防止后来人踩坑，我仍是提一下。在实现LoggerStartGrabbingConsole这个方法的时分，我测验不使用他提供的Logger结构体来给consoleGrabbersList的元素赋值，可是却呈现了卡死，卡死的调用栈跟前面一摸相同。代码如下：

void MGLoggerStartGrabbingConsole(Logger *logger)
//void MGLoggerStartGrabbingConsole()
{
    pthread_mutex_lock(&consoleGrabbersMutex);
    Boolean added = FALSE;
    for (unsigned i = 0; i < numActiveConsoleGrabbers; i++)
    {
        if (consoleGrabbersList[i] == NULL)
        {
            consoleGrabbersList[i] = logger;
            numActiveConsoleGrabbers++;
            added = TRUE;
            break;
        }
    }
    if (!added)
    {        //下面这两行不能去掉
        consoleGrabbersList = realloc(consoleGrabbersList, ++consoleGrabbersListLength * sizeof(Logger *));
        consoleGrabbersList[numActiveConsoleGrabbers++] = logger;
    }
    MGLoggerStartConsoleRedirection(); // Start redirection if necessary
    pthread_mutex_unlock(&consoleGrabbersMutex);
}

这个问题我还没有查到原因，开始猜测应该是没有目标持有Logger目标，导致他被释放了，然后引起管道呈现过错。有兴趣研讨的朋友能够一起探讨下。