strace探索QT底层工作原理(二)

360影视 2024-12-24 20:07 2

摘要:前言在上一篇文章中使用strace观察了QEventLoop的系统函数调用,帮助理解QT事件循环工作机制,本文将进一步使用strace跟踪QT跨线程信号与槽函数调用。为了方便读者理解,需要简单的解读一下

1. 前言在上一篇文章中使用strace观察了QEventLoop的系统函数调用,帮助理解QT事件循环工作机制,本文将进一步使用strace跟踪QT跨线程信号与槽函数调用。为了方便读者理解,需要简单的解读一下QThreaddata、QCoreApplication::postEvent2. QThreadData简介线程资源类QThreadData是QT框架内部的一个类,不对用户提供调用接口。使用QThread创建的每一个线程都拥有一个QThreadData。对于QThreadData普通用户只需要搞懂它的一个成员变量QPostEventList,一看名称大家就能猜得出来这个成员变量是干什么的,没错,它就QT的事件队列。class QThreadData{public://......QPostEventList postEventList;//.....};首先关注postEventList的public属性,也就是说A线程的事件队列可以被B、C、D......线程直接访问,聪明的同学会想到这样肯定会有经典的多线程data race出现,所以QPostEventList自带一个mutex。在对线程的postEventList进行读写操作前,都会先调用进行加锁操作class QPostEventList : public QVector{public:int recursion;int startOffset;int insertionOffset;QMutex mutex;};3. QCoreApplication::postEvent简介来实现。比如A线程往B线程抛送一个信号,简单来讲就是 A线程通过B线程的指针拿到B线程的postEventList,先对postEventList的mutex上锁,然后往B线程postEventList的队列添加事件。postEvent函数简化如下void QCoreApplication::postEvent(QObject *receiver, QEvent *event, int priority){//1.检查信号接收方是不是空指针if (receiver == 0) {qWarning("QCoreApplication::postEvent: Unexpected null receiver");delete event;return;}//......//2.对data->postEventList.mutex上锁,防止其它线程读写QMutexunlocker locker(&data->postEventList.mutex);//......QScopedPointer eventDeleter(event);//3.往postEventList中添加事件data->postEventList.addEvent(QPostEvent(receiver, event, priority));eventDeleter.take;event->posted = true;++receiver->d_func->postedEvents;data->canWait = false;//4.对data->postEventList.mutex解锁,允许其它线程改写locker.unlock;//5.唤醒信号接收方线程QAbstractEventDispatcher* dispatcher = data->eventDispatcher.loadAcquire;if (dispatcher)dispatcher->wakeUp;}

这里的

非常重要,且可以用strace跟踪到,本质上wakeUp函数是往B线程poll函数监听的文件描述符中写入了8个字节,来让B线程从poll监听中退出来处理事件。QEventLoop::exec可以简化成这样,在一个while循环中调用processEvents函数。int QEventLoop::exec(ProcessEventsFlags flags){//......while (!d->exit.loadAcquire)processEvents(flags | WaitForMoreEvents | EventLoopExec);//......}

·而processEvents简化后代码如下,本质就上两步,1.对本线程postEventList加锁,遍历postEventList调用订阅对应事件的槽函数;2.陷入poll函数监听,直到poll函数超时或者其他线程调用 dispatcher->wakeUp主动唤醒。

bool QEventDispatcherUNIX::processEvents(QEventLoop::ProcessEventsFlags flags){//......//1.对本线程postEventList加锁,遍历postEventList调用订阅对应事件的槽函数QCoreApplicationPrivate::sendPostedEvents(0, 0, d->threadData);//......//2.陷入poll函数监听,直到poll函数超时或者其他线程调用 dispatcher->wakeUpif (!d->interrupt.load) {// return the maximum time we can wait for an event.timespec *tm = 0;timespec wait_tm = { 0l, 0l };//计算获取定时器超时时间tmif (!(flags & QEventLoop::X11ExcludeTimers)) {if (d->timerList.timerWait(wait_tm))tm = &wait_tm;}//......//调用poll函数进入监听,并设置超时时间为tmnevents = d->doSelect(flags, tm);//.....}// return true if we handled events, false otherwisereturn (nevents > 0);}这里的简化如下void QCoreApplicationPrivate::sendPostedEvents(QObject *receiver, int event_type,QThreadData *data){//......//对data->postEventList.mutex上锁,防止其它线程写入QMutexLocker locker(&data->postEventList.mutex);//......//遍历data->postEventList,调用订阅对应事件的槽函数while (i postEventList.size) {QCoreApplication::sendEvent(r, e);}} 5. strace跟踪简单编写一个类当作工作线程,worker1的logText用于跨线程抛送sigLogText信号到日志线程,进行日志记录。Worker1::Worker1(QObject *parent): QObject{parent}{}void Worker1::logText(const QString &text){emit sigLogText(QString("threadID %1:").arg(gettid) + text, QDateTime::currentDateTime);}日志类logger向标准输出打印日志,这就是一个典型的异步日志模型。Logger::Logger(QObject *parent): QObject{parent}{}void Logger::onLogText(QString text, QDateTime time){qDebug main函数实现如下,首先打印主线程ID,然后将worker1移入子线程,建立worker1与logger的信号与槽连接。int main(int argc, char *argv){QCoreApplication a(argc, argv);printf("main threadID: %d\n", getpid);//简化日志类Logger logger;//创建worker子线程QThread *worker1Thread = new QThread;worker1Thread->setObjectName("worker1");Worker1 worker1;worker1.moveToThread(worker1Thread);QObject::connect(&worker1, &Worker1::sigLogText, &logger, &Logger::onLogText);//启动子线程worker1Thread->start;//睡眠一会,方便调用strace跟踪子线程QThread::sleep(40);//在子线程调用worker1.logTextQTimer::singleShot(0, &worker1, [&] { worker1.logText("send some data."); });//开启事件循环QEventLoop loop;loop.exec;return 0;}

使用

在子线程调用worker1.logText("send some data.");

在终端执行

strace -tt ./StraceQEventLoop

执行上述指令后,终端会输出大量带时间戳(精确到us)的系统函数调用记录,直接拉到最底下,找到以下记录。

19:42:32.207124 write(1, "main threadID: 15989\n", 21main threadID: 15989) = 2119:42:32.207720 rt_sigaction(SIGRT_1, {sa_handler=0x7ecb78491870, sa_mask=, sa_flags=SA_RESTORER|SA_ONSTACK|SA_RESTART|SA_SIGINFO, sa_restorer=0x7ecb78442520}, NULL, 8) = 019:42:32.208001 rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 019:42:32.208157 mmap(NULL, 8392704, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7ecb7460000019:42:32.208554 mprotect(0x7ecb74601000, 8388608, PROT_READ|PROT_WRITE) = 019:42:32.208884 rt_sigprocmask(SIG_BLOCK, ~, , 8) = 019:42:32.209119 clone3({flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, child_tid=0x7ecb74e00910, parent_tid=0x7ecb74e00910, exit_signal=0, stack=0x7ecb74600000, stack_size=0x7ffe40, tls=0x7ecb74e00640} => {parent_tid=[15990]}, 88) = 1599019:42:32.209959 rt_sigprocmask(SIG_SETMASK, , NULL, 8) = 019:42:32.210774 futex(0x591890f5c1a8, FUTEX_WAKE_PRIVATE, 1) = 119:42:32.211352 clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=40, tv_nsec=0}, printf("main threadID: %d\n", getpid);执行对应如下系统调用19:42:32.207124 write(1, "main threadID: 15989\n", 21main threadID: 15989) = 21从记录中可以知道主线程ID为15989。QThread *worker1Thread = new QThread;对应系统函数clone3的调用,从返回值可以得知子线程ID为15990。19:42:32.209119 clone3({flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, child_tid=0x7ecb74e00910, parent_tid=0x7ecb74e00910, exit_signal=0, stack=0x7ecb74600000, stack_size=0x7ffe40, tls=0x7ecb74e00640} => {parent_tid=[15990]}, 88) = 15990对应系统函数clock_nanosleep的调用。19:42:32.211352 clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=40, tv_nsec=0}, 0x7ffe905142c0) = 0

主线程进入sleep后,赶快新开一个终端,执行以下指令跟踪子线程系统函数调用。

sudo strace -tt -p 15990worker1子线程系统函数调用如下19:43:12.216441 newfstatat(AT_FDCWD, "/etc/localtime", {st_mode=S_IFREG|0644, st_size=561, ...}, 0) = 019:43:12.216711 newfstatat(AT_FDCWD, "/etc/localtime", {st_mode=S_IFREG|0644, st_size=561, ...}, 0) = 019:43:12.217135 gettid = 1599019:43:12.217577 write(3, "\1\0\0\0\0\0\0\0", 8) = 819:43:12.217993 poll([{fd=4, events=POLLIN}], 1, -119:43:12.216441 newfstatat(AT_FDCWD, "/etc/localtime", {st_mode=S_IFREG|0644, st_size=561, ...}, 0) = 019:43:12.216711 newfstatat(AT_FDCWD, "/etc/localtime", {st_mode=S_IFREG|0644, st_size=561, ...}, 0) = 0这个对应关系非常重要,因为软件开发需要日志记录,而日志记录需要带时间戳,而使用 newfstatat(AT_FDCWD, "/etc/localtime"的调用,知道这一点,在分析strace输出时可以快速找到软件在什么时候尝试记录日志。wakeUp唤醒日志线程(日志类放在了主线程)对应的系统调用为19:43:12.217577 write(3, "\1\0\0\0\0\0\0\0", 8) = 8往文件描述符3中写入了8个字节,以此使得日志线程退出poll监听。注意write的时间点sleep完以后的系统函数调用记录如下19:43:12.212680 write(4, "\1\0\0\0\0\0\0\0", 8) = 819:43:12.213204 poll([{fd=3, events=POLLIN}], 1, 0) = 1 ([{fd=3, revents=POLLIN}])19:43:12.213602 read(3, "\1\0\0\0\0\0\0\0", 16) = 819:43:12.214065 poll([{fd=3, events=POLLIN}], 1, -1) = 1 ([{fd=3, revents=POLLIN}])19:43:12.218037 read(3, "\1\0\0\0\0\0\0\0", 16) = 819:43:12.224095 write(2, "\"2024-12-22 19:12:12 213\" \"threa"..., 59"2024-12-22 19:12:12 213" "threadID 15990:send some data.") = 5919:43:12.224396 poll([{fd=3, events=POLLIN}], 1, -1^C) = ? ERESTART_RESTARTBLOCK (Interrupted by signal)19:43:12.214065,导致第二次poll函数退出监听是因为文件描述符3有数据可以读。而worker1线程write函数调用时间点为19:43:12.217577,因此可以推断出第二次poll函数退出监听是因为worker1线程抛出的sigLogText信号。函数执行qDebug 对应的系统调用为19:43:12.224095 write(2, "\"2024-12-22 19:12:12 213\" \"threa"..., 59"2024-12-22 19:12:12 213" "threadID 15990:send some data.") = 5919:43:12.21644119:43:12.2240956. 线程退化

有两种情况会导致线程退化,使并行工作变成串行。

1. 假如我们有100个工作线程尝试往日志线程写入数据,本来这100个工作线程想要并行工作,但是向日志线程抛送sigLogText信号会对日志线程的事件队列postEventList上锁,如果此刻A线程上锁日志线程的postEventList向事件队列中添加事件,那么其他99个线程就只有等着。

QEventLoop::processEventsQCoreApplicationPrivate::sendPostedEvents时自己将postEventList锁住,处理日志线程堆积的事件。对于系统write函数,日志每次调用write函数写入日志,大多时候只是将日志写入到缓存区,这种情况下write函数执行非常快(1us级别),但是如果这次write调用刚好导致缓存区满了,系统会一次性将缓存区的数据flush到硬盘上,以上过程笔者见过有些电脑会耗时10ms。就是这10ms导致笔者在上面踩过坑。基于QT开发UI软件的程序员,可能写过如下代码//1.向外部发送数据sendData;//2.抛送信号异步记录发送数据日志//3.开启一个事件循环等待接外部返回数据m_loop.exec;正常情况下,会在接收外部数据的槽函数或注册一个QTimer超时调用m_loop.quit来退出事件循环阻塞。

在第1步执行完后,正常情况下第2步抛送信号异步记录发送数据日志是us级别调用,但是刚好日志线程自己先锁住postEventList,遍历日志线程事件队列执行日志写入操作,这一次的write函数调用导致缓存区满了需要flush耗时操作。等到日志线程解锁postEventList,工作线程拿到日志线程的postEventList往其中添加日志事件时已经过去了10ms。最后导致第1步和第3步之间执行的时间点相差了10ms以上,导致了奇怪的现象出现(上述发送数据通过事件循环阻塞的方式没有问题,是笔者接收数据的逻辑错误导致的)。

7. 后记

至此我们完成了strace分析QT的信号与槽工作原理。strace工具在我们分析某些奇怪的bug时,会有奇效,希望借文本抛砖引玉,为读者提供一些思路。

来源:搭配灵感盒

相关推荐