探究原因
基本上这种事情一定可以在Apple文档中找到,看NSLog的文档,第一句话就说:Logs an error message to the Apple System Log facility.,所以首先,NSLog就不是设计作为普通的debug log的,而是error log;其次,NSLog也并非是printf的简单封装,而是Apple System Log(后面简称ASL)的封装。
ASL
ASL是个啥?从官方手册上,或者从终端执行man 3 asl都可以看到说明:
These routines provide an interface to the Apple System Log facility. They are intended to be a replacement for the syslog(3) API, which will continue to be supported for backwards compatibility.
大概就是个系统级别的log工具吧,syslog的替代版,提供了一系列强大的log功能。不过一般我们接触不到,NSLog就对它提供了高层次的封装,如这篇文档所提到的:
You can use two interfaces in OS X to log messages: ASL and Syslog. You can also use a number of higher-level approaches such as NSLog. However, because most daemons are not linked against Foundation or the Application Kit, the low-level APIs are often more appropriate
一些底层相关的守护进程(deamons)不会link如Foundation等高层框架,所以asl用在这儿正合适;而对于应用层的用NSLog。
在CocoaLumberjack的文档中也说了NSLog效率低下的问题:
NSLog does 2 things:
- It writes log messages to the Apple System Logging (asl) facility. This allows log messages to show up in Console.app.
- It also checks to see if the application’s stderr stream is going to a terminal (such as when the application is being run via Xcode). If so it writes the log message to stderr (so that it shows up in the Xcode console).
To send a log message to the ASL facility, you basically open a client connection to the ASL daemon and send the message. BUT - each thread must use a separate client connection. So, to be thread safe, every time NSLog is called it opens a new asl client connection, sends the message, and then closes the connection.
意识大概是说,NSLog会向ASL写log,同时向Terminal写log,而且同时会出现在Console.app中(Mac自带软件,用NSLog打出的log在其中全部可见);不仅如此,每一次NSLog都会新建一个ASL client并向ASL守护进程发起连接,log之后再关闭连接。所以说,当这个过程出现N次时,消耗大量资源导致程序变慢也就不奇怪了。
时间和进程信息
主要原因已经找到,还有个值得注意的问题是NSLog每次会将当前的系统时间,进程和线程信息等作为前缀也打印出来,如:
2012-34-56 12:34:56.789 XXXXXXXX[36818:303] xxxxxx
当然这些也可能是作为ASL的参数创建的。