Taming Leopard’s syslogd
Comments(11) A short while after upgrading to Leopard, I began experiencing a problem where the syslogd daemon would begin to hog the CPU, causing my Macbook Pro to whirr noisily (in a fashion that made me feel like I should be running some sort of “pre-flight checks” prior to taking off in a jet plane).
Furthermore, this only seemed to occur when I was doing something really important (like backing up to Time Machine, or running VMware Fusion).
Further investigation online saw that other people were having similar issues[1][2], and that it’s caused by a mysterious overgrown log file[1].
It seems Apple have may have updated syslogd in Leopard to now log to a “data store” (located at /var/log/asl.db) that is searchable using syslog(1). According to syslogd(8), this data store is pruned nightly and on system boot-up (for those who don’t keep their computer switched on at night).
Unfortunately, I rarely reboot, and my computer is usually asleep when I am. This causes the data store to fill up without being pruned, which is the apparent cause of syslogd going nuts when the data store grows too large.
To make the problem go away, you can prune your data store. Here is the quick and dirty way to delete the entire data store:
sudo launchctl unload com.apple.syslogd.plist
sudo rm /var/log/asl.db
sudo launchctl load com.apple.syslogd.plist
To prune it the proper way, use the syslog command (syslog(1)). For example, to remove all messages older than one day, run:
sudo syslog -p -k Time ge 1d
See syslog(1) for more information about pruning using different expressions.
As a permanent solution, some people online suggest setting the cutoff (-c) option for syslogd to 0[3] (so that it never logs to the data store). If you’d like to give this a go, you’ll need to modify this launchd plist file: /System/Library/LaunchDaemons/com.apple.syslogd.plist (read on).
Firstly, stop syslogd
sudo launchctl unload com.apple.syslogd.plist
Open up the syslogd.plist file for launchd:
sudo vi /System/Library/LaunchDaemons/com.apple.syslogd.plist
Find the following line (on an unmodified version, line 23):
<string>/usr/sbin/syslogd</string>
Add these lines after:
<string>-c</string>
<string>0</string>
Start syslogd again:
sudo launchctl load com.apple.syslogd.plist
I assume people who reboot their computer regularly aren’t likely to see this behaviour, but hopefully some time in the future Apple can optimise the syslogd daemon to fix this problem.
I prefer to start syslogd this way
syslogd -ttl 3600 -sweep -c 4
Notice level is not logged (some apps log lots of notice level msgs)
Time to live: 1 hour
Clean the database every hour
Sorry,
syslogd -ttl 3600 -sweep 3600 -c 4
Thanks for your work on this problem. It has been driving me crazy because there seems to be so many ideas on stopping it. Like everyone is identifying symptoms while the cause continues to go undetected. This has been the most solid info I’ve found on the problem. Thanks and Good Work!
[...] likely solution has been provided by Daniel Simmons, who wrote the article ‘Taming Leopard’s Syslogd‘ on the subject. Unfortunately I did not find this solution until solving the quandary using [...]
It could be possible that I am holding the key to this problem on my computer, but don’t know where to look exactly.
I am able to cause the syslogd to go haywire.
The problem is likely related to a damaged or unclosed file left on my drive after the forced reboot with 0 bytes available. Other people might also have a situation with problems caused by a forced reboot or power failure that leeds to the into the syslogd problem. Since in my case it was obviously related to iTunes, I tried renaming my iTunes Library, with success, iTunes appears normal again (without any music and podcasts) and also the syslogd doesn’t reappear as CPU hog.
if I put my iTunes Library file back in place, the problem will also be back. So how can I use this fact to help you finding the true cause of the chain reaction? How can I see what iTunes sends to or requests from the syslogd prior to it going haywire?
This could hold the key to a general solution of the yet unidentified cause. It is not a fix but request for deeper investigation.
G.
Gianni,
It hasn’t been previously mentioned, but I have found that the actual cause for syslogd hogging CPU is usually when an application is writing very heavily to syslogd.
The CPU hogging itself is then caused by syslogd’s inability to handle these log messages efficiently.
In your case, I would fire up Console.app and have a log at messages in the “LOG DATABASE QUERIES” sections. If my theory is correct, you may find iTunes is complaining about something several times per second (eg. the same log message repeated hundreds of times).
This still doesn’t really help us though. From my point of view, the fault still lies with syslogd. I’d be interested to see what you find.
Cheers,
Dan.
did my last post with the clip from the log entries get through? I got a strange browser message on pressing submit.
Indeed Dan.
Both iTunes and the quicklook engine are having some repeated failure communicating with QuickTime (OQT_MovieImport) causing a heavy load on the system.log in my case.
In the few days last week that I took time to analyze this, my system.log contained 3,697,105 “outside of file” entries all very alike the ones below. Almost 4 million lines, were created in a matter of minutes, lines were created with multiple hundreds per second.
What could Apple do to make the syslogd ignore applications like iTunes creating such heavy loads. ?
Fortunately I was able to dig deeper and delete the file that iTunes had open at the time of the problem. This simple deleting of one .m4v source (video podcast) eliminated the CPU Hog it’s hasn’t returned in the past 5 days.
example from the /var/log/system.log file:
Aug 20 00:45:45 [0x0-0x1a01a].com.apple.iTunes[164]: OQT_MovieImport: fseek_store: tried to seek to 154640663; outside of file
Aug 20 00:45:45 [0x0-0x1a01a].com.apple.iTunes[164]: OQT_MovieImport: fseek_store: tried to seek to 154640671; outside of file
Aug 20 00:45:45 [0x0-0x1a01a].com.apple.iTunes[164]: OQT_MovieImport: fseek_store: tried to seek to 288858399; outside of file
Aug 20 00:45:45 [0x0-0x1a01a].com.apple.iTunes[164]: OQT_MovieImport: fseek_store: tried to seek to 288858407; outside of file
Aug 20 00:45:45 [0x0-0x1a01a].com.apple.iTunes[164]: OQT_MovieImport: fseek_store: tried to seek to 423076135; outside of file
Aug 20 00:45:45 [0x0-0x1a01a].com.apple.iTunes[164]: OQT_MovieImport: fseek_store: tried to seek to 423076143; outside of file
Aug 20 00:45:45 [0x0-0x1a01a].com.apple.iTunes[164]: OQT_MovieImport: fseek_store: tried to seek to 557293871; outside of file
Aug 20 00:45:45 [0x0-0x1a01a].com.apple.iTunes[164]: OQT_MovieImport: fseek_store: tried to seek to 557293879; outside of file
Aug 20 00:45:45 [0x0-0x1a01a].com.apple.iTunes[164]: OQT_MovieImport: fseek_store: tried to seek to 691511607; outside of file
Aug 20 00:45:45 [0x0-0x1a01a].com.apple.iTunes[164]: OQT_MovieImport: fseek_store: tried to seek to 691511615; outside of file
Aug 20 00:45:45 [0x0-0x1a01a].com.apple.iTunes[164]: OQT_MovieImport: fseek_store: tried to seek to 825729343; outside of file
Aug 20 00:45:45 [0x0-0x1a01a].com.apple.iTunes[164]: OQT_MovieImport: fseek_store: tried to seek to 825729351; outside of file
Aug 20 00:45:45 [0x0-0x1a01a].com.apple.iTunes[164]: OQT_MovieImport: fseek_store: tried to seek to 959947079; outside of file
Aug 20 00:45:45 [0x0-0x1a01a].com.apple.iTunes[164]: OQT_MovieImport: fseek_store: tried to seek to 959947087; outside of file
Aug 20 00:45:45 [0x0-0x1a01a].com.apple.iTunes[164]: OQT_MovieImport: fseek_store: tried to seek to 1094164815; outside of file
Aug 20 00:45:45 [0x0-0x1a01a].com.apple.iTunes[164]: OQT_MovieImport: fseek_store: tried to seek to 1094164823; outside of file
Aug 20 00:45:45 [0x0-0x1a01a].com.apple.iTunes[164]: OQT_MovieImport: fseek_store: tried to seek to 1228382551; outside of file
Aug 20 00:45:45 [0x0-0x1a01a].com.apple.iTunes[164]: OQT_MovieImport: fseek_store: tried to seek to 1228382559; outside of file
Ah! That explains it then.
It is my understanding that Apple’s new syslog database hasn’t replaced writing to system.log, so in theory one could safely disable logged to the database to permanently remove this problem without losing logging functionality.
Interesting, nonetheless. Thanks for your input. I think this really hits the nail on the head in regards to this issue.
Perfect,
Thanks for tip about disabling the logging.
And, guess what.. only a few houres after my post I had the same problem back. This time caused by the the QuickTime Player.app and not iTunes. Again it’s related to mp4 video file. By the was even much more that hundreds of entries, to be exact, my MacBook was able to write 19125 log entries per second.
Maybe you want to start a new topic since this issue obviously is not concerning syslogd anymore.
example from my recent /var/log/system.log file:
Aug 25 17:39:42 [0x0-0x24d24d].com.apple.quicktimeplayer[98605]: OQT_MovieImport: fseek_store: tried to seek to 54530118982374; outside of file
Aug 25 17:39:42 [0x0-0x24d24d].com.apple.quicktimeplayer[98605]: OQT_MovieImport: fseek_store: tried to seek to 54530253200102; outside of file
Aug 25 17:39:42 [0x0-0x24d24d].com.apple.quicktimeplayer[98605]: OQT_MovieImport: fseek_store: tried to seek to 54530253200110; outside of file
Aug 25 17:39:42 [0x0-0x24d24d].com.apple.quicktimeplayer[98605]: OQT_MovieImport: fseek_store: tried to seek to 54530387417838; outside of file
Aug 25 17:39:42 [0x0-0x24d24d].com.apple.quicktimeplayer[98605]: OQT_MovieImport: fseek_store: tried to seek to 54530387417846; outside of file
Aug 25 17:39:42 [0x0-0x24d24d].com.apple.quicktimeplayer[98605]: OQT_MovieImport: fseek_store: tried to seek to 54530521635574; outside of file
Aug 25 17:39:42 [0x0-0x24d24d].com.apple.quicktimeplayer[98605]: OQT_MovieImport: fseek_store: tried to seek to 54530521635582; outside of file
Aug 25 17:39:42 [0x0-0x24d24d].com.apple.quicktimeplayer[98605]: OQT_MovieImport: fseek_store: tried to seek to 54530655853310; outside of file
Aug 25 17:39:42 [0x0-0x24d24d].com.apple.quicktimeplayer[98605]: OQT_MovieImport: fseek_store: tried to seek to 54530655853318; outside of file
Aug 25 17:39:42 [0x0-0x24d24d].com.apple.quicktimeplayer[98605]: OQT_MovieImport: fseek_store: tried to seek to 54530790071046; outside of file
if you are searching more details and a fix to this “OQT_MovieImport: fseek_store: tried to seek to; outside of file” being endlessly written to your log read this post: http://forums.mactalk.com.au/13/43557-itunes-7-6-syslogd-things-going-badly.html#post438724