前几天我在OpenSIPS中使用了usrloc模块,然后发现有时候日志会突然频繁打印:
timer_ticker: timer task <ul-timer> already scheduled
在此期间,服务无法响应SIP请求。
排查过程如下:
1. 使用usrloc后出现的问题,并且日志也指明了方向:ul-timer
查看代码,ul-timer这个定时任务负责定期清理过期的contacts,涉及内存操作和数据库操作。第一反应,数据库操作耗时太久,导致执行定时任务的进程被卡死了。gdb到各个子进程中,发现阻塞在poll wait上。
OpenSIPS中,名为"Timer"的进程负责定时器任务的调度,将任务对象的指针写入管道。"SIP receiver"、"TCP receiver"、"Timer handler" 这几个进程,都可能从管道读到定时器任务执行,如果所有的"SIP receiver" 读到定时器任务并陷入执行,那对外的表现就是服务无法响应SIP请求了。
2. 排查这些数据库操作,都是很简单的update、delete,正常应该很快返回
加了日志打印下耗时,发现出现问题的时候,1-2分钟数据库操作才返回。难道是libpq有bug?在libpq里加打印调试、并阅读libpq官方文档,至此已经花了2天时间,但仍然没有定位问题。
3. 发现OpenSIPS DB操作并未加锁,有些奇怪,然后natstat看了下OpenSIPS数据库端口的使用,发现竟然只有一条连接。
一条连接,还不加锁,这肯定有问题,甚至可能导致A进程把应该B进程读取的数据库数据抢过去了。
那么为什么只有一条连接呢?原来我新开发的模块,和修改过的load_balancer模块中,把数据库连接初始化的操作都放到mod_init函数中了,而OpenSIPS fork工作进程是在加载模块之后做的,这就导致了数据库连接pool被fork到工作进程中,同一个连接地址,大家用的是同一条连接!
最后将连接初始化延迟到了使用时,解决了这个问题。