调试信号量dispatch_semaphore

使用三方库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,于是需要对其调试定位问题所在。

首先考虑肯定是线程锁没有起作用,那就断点调试一下:


image.png
image.png

通过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时,可以看到联想的属性列表:

image.png

在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,从而得到了我们期望的值。这里其实第二个参数就没有实际作用了。

总结:

  1. 信号量直接打印%@,无法显示已经开启的信号数量,因为此时使用的是x.description, 并且比xcode的debug断点时看到的信息少,此时应该使用x.debugDescription,此时的显示信息即断点可查看的信息相符

  2. 通过打印信号量,查看其中value值可以判断信号数量,当creat为1时,最多value只能为1,如果有2的情况,说明未起作用

  3. 当信号量未起作用,可以从两方面考虑:
    超时时间设置错误,例如很短的超时时间,或者参数传递的是dispatch_time变量其实就是0.
    是否有重复signal的地方,即与wait不配对

  4. 信号量引起死锁:当后面进来wait信号量的线程与前面已经等到信号但还未signal的signal所处是同一个线程时,由于wait阻塞了线程,导致signal一直无法进入,一直无法释放,wait死锁在那。

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 203,324评论 5 476
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 85,303评论 2 381
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 150,192评论 0 337
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,555评论 1 273
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,569评论 5 365
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,566评论 1 281
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 37,927评论 3 395
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,583评论 0 257
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 40,827评论 1 297
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,590评论 2 320
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,669评论 1 329
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,365评论 4 318
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 38,941评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,928评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,159评论 1 259
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 42,880评论 2 349
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,399评论 2 342

推荐阅读更多精彩内容

  • Managing Units of Work(管理工作单位) 调度块允许您直接配置队列中各个工作单元的属性。它们还...
    edison0428阅读 7,931评论 0 1
  • 本文为转载资料,原文地址: http://www.jianshu.com/p/02821f9d7777 一、信号量...
    一曰就是一天阅读 1,124评论 0 3
  • 泰戈尔说过‘只管走下去,不必逗留着去采集鲜花去保存,因为一路上,花朵自会继续开放的。’ 过了高三,人生也算...
    痞猫ii阅读 748评论 4 2
  • 每次声嘶力竭地看完一本书后 芸落一般会幡然醒悟 发誓再也不看了 权当最后一本 不过前段日子 似乎嗅到了灵魂腐朽的味...
    聊胜于无中阅读 267评论 0 0
  • 内部结构 核心 回归本质,做好一个孵化器的基础核心,和创业项目一样,只有:人。重视孵化器的运营人员,设置合理的公司...
    梅晨斐阅读 1,070评论 0 6