在OSX 10.10上延迟代码执行 [英] Delaying Code Execution on OSX 10.10

问题描述

我遇到了一个非常奇怪的问题，该问题影响了仅在OSX 10.10系统上运行的代码.我已经看到在运行我的代码的超过25个OSX 10.10系统上发生了这种异常，而 exact 相同的代码在升级之前并没有表现出这种现象(10.7).此外，此问题并非100％可重现，因为它随机发生〜0-5％的时间.在测试代​​码时，机器上没有发生其他关键或CPU耗尽的情况.即使发生了其他事情，我所经历的延误太长了，这荒谬的事实使这个结论似乎令人怀疑.无论如何，不​​用费劲，就看看下面的NSLog打印:

I've encountered a very strange issue that affects my code running only on OSX 10.10 systems. I've seen this anomaly occur on over 25 OSX 10.10 systems running my code, whereas the exact same code did not exhibit this behavior before upgrading (10.7). Furthermore, this issue is not 100% reproducible in that it occurs randomly ~0-5% of the time. While testing the code, nothing else critical or CPU exhaustive is occurring on the machine. Even if something else was happening, the very fact that the delays I'm experiencing are soooo ridiculously long make that conclusion seem suspicious. Anyhow, without further ado, take a look at the following NSLog prints:

12:00:05.766 MyApp[59957:6540517] Time_To_Wait: 679000000, Fire_Date: 270946738287700, Cur_Date: 270946059302734
12:00:26.446 MyApp[59957:6540517] Resume...

时间以纳秒为单位.根据NSLog时间戳，我们实际上实际上等待了20.68秒，而不是期望的0.679秒.现在，让我们看一下代码:

The times are in nanoseconds. According to the NSLog timestamps, we actually ended up waiting 20.68 seconds, rather than the desired 0.679 secs. Now, let's take a look at the code:

NSLog(@"Time_To_Wait: %lld, Fire_Date: %lld, Cur_Date: %lld", time_to_wait, fire_date, mach_absolute_time());
mach_wait_until(fire_date);
NSLog(@"Resume...");

如果您想知道mach_wait是什么，它是高分辨率计时器可用的默认值.只需包含

In case you're wondering what mach_wait is, it's a high resolution timer available default. Just include

#include <mach/mach.h>
#include <mach/mach_time.h>

但这没关系，因为如果我将mach_wait_until替换为:

But that doesn't matter because I've experienced the exact same issue if I replace mach_wait_until with:

• sleep()
• usleep()
• [NSThread sleepForTimeInterval:]
• GCD's dispatch_after(,^{});
• mach_wait_until()

• sleep()
• usleep()
• [NSThread sleepForTimeInterval:]
• GCD's dispatch_after(,^{});
• mach_wait_until()

不管我尝试使用哪种延迟方法，我都使用NSLog将我的"delay"值打印到控制台以进行健全性检查，以确保它是正确的毫秒数，然后执行上述操作之一.大约有95％的时间会按照规范运行.但偶尔，我会得到一些重击延迟，例如10到20秒.是什么赋予了?这是优胜美地内核的问题吗?同样，我从未体验过在10.7上运行相同的代码的情况.而且我已经测试了上述所有用于延迟代码执行的方法.

Doesn't matter what method of delay I try to use, I use NSLog to print my 'delay' value to the console as a sanity check to ensure it's the correct # of ms, then fire one of the above. ~95% of the time it behaves according to specification. But occasionally randomly, I'll get some whack delay like 10-20 seconds. What gives? Is this some Yosemite kernel issue? Again, I've never experienced this w/ the same code running on 10.7. And I've tested all of the above methods for delaying the execution of code.

更新:

根据评论建议，我继续进行sudo dtruss -f -e sudo -u USER MyApp 2> ~/myapps.log.像往常一样，大多数的mach_wait和睡眠行为都按照他们应该的方式进行.为了使事情更容易识别，我添加了一项检查，在该检查中，如果实际睡眠持续时间大于应有的预期睡眠时间的3倍，则会打印出延迟问题.运行我的程序，并搜索延迟问题.下面列出了在紧接在mach_wait语句之前和之后的日志打印之间发生的最频繁的系统调用(dtruss输出):

Following comment advice, I went ahead and sudo dtruss -f -e sudo -u USER MyApp 2> ~/myapps.log. As usual, most of the mach_wait's and sleeps behaved the way they were supposed to. So to make things easier to identify, I added in a check where if the actual sleep duration is > 3x what it's supposed to be, it prints out DELAY ISSUE. Ran my program and did a search for delay issue. Listed below are the most frequent system calls (dtruss output) that occur between the log print immediately preceding and succeeding the mach_wait statements:

• 99613/0xcf33b9:30250 __semwait_signal(0xD07，0x0，0x1)= -1 Err#60
• 99613/0xcf33b9:16 workq_kernreturn(0x20、0x0、0x1)= 0 0

以上两个电话中约有250个以上.可能比__semwait多一些.无论什么时间，整个学期等待通常要花费大约30000个单位"的时间.邓诺(Dunno)阴郁的时光.这些占了电话的大部分.

There are about ~250+ of the above two calls. Probably a few more workq than __semwait's. The semwait's all usually take about 30000 'units' of time to complete, whatever that is. Dunno how dtruss times. These make up the bulk of the calls.

• 752/0xcf3320:2787191 kevent64(0x3，0x0，0x0)= 1 0
• 752/0xcf335d:189948 select(0x40、0x7FC080E18220、0x7FC080E13B40、0x0、0x0)= 1 0
• 752/0xcf335d:1648403 select(0x40，0x7FC080E18220，0x7FC080E13B40，0x0，0x0)= 1 0

这三个系统调用花费的时间单位最长.在〜20秒的等待间隔中，它们每个都在输出中出现一次.

These three system calls took the longest # of units of time. And they were each appeared once in the output during our ~20sec wait gap.

不确定如何使用上述= X

Not sure what to do with the above =X

推荐答案

查看上面的评论

问题似乎与Apple的 Timer Coalescing 有关，后者是Mac OS X 10.9 Mavericks的一项新功能，可以将计时器的触发时间调整至几毫秒以合并它们，从而允许处理器，以减少电源状态转换并保持更长的空闲时间.好处是大大降低了功耗.

The problem appears to be connected to Apple's Timer Coalescing, a new feature in Mac OS X 10.9 Mavericks that rejigs the firing times of timers by up to a few milliseconds to merge them, thus allowing the processor to make fewer power-state transitions and to remain idle for longer. The benefit is greatly reduced power consumption.

Apple简短提及该主题的白皮书为这里.

A white paper by Apple on the topic that mentions it briefly is here.

注释中保留的解决方案是禁用TC，如下所示:

The solution that was retained in the comments is to disable TC, as follows:

sudo sysctl -w kern.timer.coalescing_enabled=0

这篇关于在OSX 10.10上延迟代码执行的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！