使用三方库CMVoipMulticastDelegate过程中,发现此库并没有添加线程保护相关逻辑,会导致对delegateNodes操作时产生crash:Collection <__NSArrayM: 0xb550c30> was mutated while being enumerated, 这时由于在枚举delegateNodes时,恰好有对这个数组的操作,如增删改等。
最懒的操作就是每次枚举之前copy一份,使用copy出来的数组进行枚举,但这个方法存在数据错误风险。最好的方式当然是进行线程安全的处理,基于性能考虑,我使用了信号量来处理。但是却在其中引入错误,初始 ** 错误代码 ** 如下:
@implementation CMVoipMulticastDelegate
- (id)init
{
if ((self = [super init]))
{
delegateNodes = [[NSMutableArray alloc] init];
signal = dispatch_semaphore_create(1);
overTime = dispatch_time(DISPATCH_TIME_NOW, DISPATCH_TIME_FOREVER);//DISPATCH_TIME_FOREVER;
serialQueue = dispatch_queue_create("com.hycmcc.CMVoipMulticastDelegate", DISPATCH_QUEUE_SERIAL);
}
return self;
}
- (void)semaphore_signal_in_global_queue
{
// signal始终放在一个线程中,一是保证不会因为wait和signal在一个线程导致死锁,二是避免过多新建线程造成资源浪费
dispatch_async(serialQueue, ^{
dispatch_semaphore_signal(signal);
});
}
- (void)addDelegate:(id)delegate delegateQueue:(dispatch_queue_t)delegateQueue
{
if (delegate == nil) return;
if (delegateQueue == NULL) delegateQueue = dispatch_get_main_queue();
CMVoipMulticastDelegateNode *node =
[[CMVoipMulticastDelegateNode alloc] initWithDelegate:delegate delegateQueue:delegateQueue];
dispatch_semaphore_wait(signal, overTime);
CMVoIPLogInfo(@"CMVoipMulticastDelegate addDelegate");
[delegateNodes addObject:node];
[self semaphore_signal_in_global_queue];
}
这份代码在调试时,还是会出现上面的crash,于是需要对其调试定位问题所在。
首先考虑肯定是线程锁没有起作用,那就断点调试一下:
通过xcode断点,并在下面观察区,点击signal属性,右键选择“print description of signa” ,可以在控制台打印signal的值。或者通过lldb指令:
(lldb) po signal
<OS_dispatch_semaphore: semaphore[0x1c02892e0] = { xref = 1, ref = 1, port = 0x25351, value = 0, orig = 1 }>
观察到这个打印的值,那现在可以考虑是可以将其中这几个值都分别打印出来,或者判断其中某一个值,超过1,说明线程数字超过1了,就是问题出现了。
但是这个OS_dispatch_semaphore是底层c的数据结构,无法通过属性直接获取,或者通过结构体->形式引用到其中的值。 所以只能通过打印这个OS_dispatch_semaphore,通过日志来分析(单步debug很难复现多线程问题)。
所以就添加了打印语句:
CMVoIPLogInfo(@"CMVoipMulticastDelegate signal:%@", signal);
结果如下:
<OS_dispatch_semaphore: semaphore[0x1c02892e0]>
可见其中并没有{ xref = 1, ref = 1, port = 0x25351, value = 0, orig = 1 } 数据结构中具体元素的值,难道是需要使用description ?
更改打印语句如下:
CMVoIPLogInfo(@"CMVoipMulticastDelegate signal:%@", signal.description);
结果如下:
<OS_dispatch_semaphore: semaphore[0x1c02892e0]>
怎么还是这样!
按理说,lldb的调试时的上下文和打印语句应该是一样的,应该可以拿到同样的数据,为什么打印不出来同样的值呢? 那我们就尝试下是不是有其他属性可以将断点时的值复现出来,当我们随便输入一个字母d时,可以看到联想的属性列表:
在description属性下面还有一个debugDescription属性,尝试一下结果如下:
<OS_dispatch_semaphore: semaphore[0x1c02892e0] = { xref = 1, ref = 1, port = 0x25351, value = 0, orig = 1 }>
原来debugDescription属性时专门用来调试的,iOS系统的对象数据结构图设计的还真是不错,所以我们日常开发时,一些类或者model设计时,为了便于调试,也应该分别重写debugDescription和description两个属性。
这时,我们就可以在合适的地方添加log语句来看问题了,日志精简如下:
2018-07-09 14:32:18:260 cMeeting[41681:4166517] CMVoipMulticastDelegate semaphore+1 before <OS_dispatch_semaphore: semaphore[0x1c02897e0] = { xref = 1, ref = 1, port = 0x25351, value = 0, orig = 1 }>
2018-07-09 14:32:18:260 cMeeting[41681:4166517] CMVoipMulticastDelegate semaphore+1 after <OS_dispatch_semaphore: semaphore[0x1c02897e0] = { xref = 1, ref = 1, port = 0x25351, value = 1, orig = 1 }>
2018-07-09 14:32:18:358 cMeeting[41681:4166880] CMVoipMulticastDelegate semaphore-1 before <OS_dispatch_semaphore: semaphore[0x1c02897e0] = { xref = 1, ref = 1, port = 0x25351, value = 2, orig = 1 }>
可以看到,value是当前线程数,当出现大于1 的情况,就说明问题出现了(我们已经设置了最大并发数是1)。
我们这时首先判断是不是重复调用了dispatch_semaphore_signal方法,导致释放了多余信号,例如释放了两个信号的话,就会导致两个在等待dispatch_semaphore_wait的线程同时获得信号,而进入相关操作代码中,导致crash。
经过代码走查,和日志分析,并没有这种情况。
经过日志和debug调试,我们发现在出现value = 1,即已经有一个线程获得信号之后,其他线程在dispatch_semaphore_wait方法处没有阻塞等待,而是直接开始执行后面代码,也就是说这里信号量确实没有起到限制并发线程数目的作用。
那么问题在哪呢?
是超时时间没起作用? 还是信号量使用有问题?
经过查阅其他人使用信号量的方式,惊人的发现,overTime这里虽然要求是dispatch_time 类型,但是正确的却是直接使用DISPATCH_TIME_FOREVER,而不是如上面所示的dispatch_time(DISPATCH_TIME_NOW, DISPATCH_TIME_FOREVER);
查看dispatch的源码也能判断到这里的错误所在:
dispatch_time_t
dispatch_time(dispatch_time_t inval, int64_t delta)
{
if (inval == DISPATCH_TIME_FOREVER) {
return DISPATCH_TIME_FOREVER;
}
if ((int64_t)inval < 0) {
// wall clock
if (delta >= 0) {
if ((int64_t)(inval -= delta) >= 0) {
return DISPATCH_TIME_FOREVER; // overflow
}
return inval;
}
if ((int64_t)(inval -= delta) >= -1) {
// -1 is special == DISPATCH_TIME_FOREVER == forever
return -2; // underflow
}
return inval;
}
// mach clock
delta = _dispatch_time_nano2mach(delta);
if (inval == 0) {
inval = mach_absolute_time();
}
if (delta >= 0) {
if ((int64_t)(inval += delta) <= 0) {
return DISPATCH_TIME_FOREVER; // overflow
}
return inval;
}
if ((int64_t)(inval += delta) < 1) {
return 1; // underflow
}
return inval;
}
这个函数逻辑比较简单,当我们错误的使用dispatch_time(DISPATCH_TIME_NOW, DISPATCH_TIME_FOREVER);这种形式时,对应函数的入参inval 和 delta分别是DISPATCH_TIME_NOW和DISPATCH_TIME_FOREVER,而二者宏定义的值为:
#define DISPATCH_TIME_NOW 0
#define DISPATCH_TIME_FOREVER (~0ull)
所以此函数就会经下面逻辑将inval返回,
if (inval == 0) {
inval = mach_absolute_time();
}
也就是说返回的就是mach_absolute_time(),获取到的是当前系统的时间。 信号量在判断返回的时间时判断到此时刻,发现已经过去了,那么直接就不等待而直接执行下面的代码,从而没有实现阻塞的目的。
所以从这个函数我们也能看出,我们正确的使用方式应该是:
dispatch_time(DISPATCH_TIME_FOREVER, DISPATCH_TIME_NOW);
这样会通过下面的逻辑:
if (inval == DISPATCH_TIME_FOREVER) {
return DISPATCH_TIME_FOREVER;
}
直接返回DISPATCH_TIME_FOREVER,从而得到了我们期望的值。这里其实第二个参数就没有实际作用了。
总结:
信号量直接打印%@,无法显示已经开启的信号数量,因为此时使用的是x.description, 并且比xcode的debug断点时看到的信息少,此时应该使用x.debugDescription,此时的显示信息即断点可查看的信息相符
通过打印信号量,查看其中value值可以判断信号数量,当creat为1时,最多value只能为1,如果有2的情况,说明未起作用
当信号量未起作用,可以从两方面考虑:
超时时间设置错误,例如很短的超时时间,或者参数传递的是dispatch_time变量其实就是0.
是否有重复signal的地方,即与wait不配对信号量引起死锁:当后面进来wait信号量的线程与前面已经等到信号但还未signal的signal所处是同一个线程时,由于wait阻塞了线程,导致signal一直无法进入,一直无法释放,wait死锁在那。