Monday, March 13, 2017

Sierra Logging Spew

Lloyd Chambers:

Opening Console, you’ll see the ceaseless spew from a cornucopia of processes, including many I never want, and will never use. It might be ‘quiet’ at times, but what I’ve found is that a number of Apple services get triggered from time to time to go into a state of endless bitching and moaning, often with messages that equate to “fix this bug someday”.

For example, here is this lovely new Apple bug involving touchui. On a Mac Pro no touch user interface exists, but the engineers at Apple don’t bother to test much any more, so the com.apple.nowplayingtouchui apparently is just going to fail forever.

The spew has been getting worse the last few versions of macOS, and it’s also more of a problem with 10.12 and its new logging subsystem. I’m running into more cases of runaway logging where the same message is repeated multiple times per second. Not only does this hog the CPU, but Console falls behind so that (even with a filter to hide the spew) it can take minutes for actual, relevant log entries to show up. The only remedy seems to be to restart the Mac.

Previously: Sierra Log Littering.

34 Comments RSS · Twitter

Burns through disc write cycles too, so bad for SSDs.

I suspect this is the reason why versions of OS X since around Yosemite have dragged on computers with traditional rotational hard disks – there's just masses of log writing going on, at every moment, and especially during important times when the computer is booting or launching an app. Aa a independent Mac IT guy I hear this all the time – since installing Yosemite my Mac has been slow as molasses. The solution always is to install an SSD.

Can log writing be turned off?

@Keir I think there’s something to that. I recently set up a clean Sierra system on an old Apple/WD hard drive from 2006 that I had lying around. It’s unusably slow when connected to my current MacBook Pro via Thunderbolt. That is, many minutes to boot or to launch an app, 10-second pauses for buttons to respond, laggy typing, etc. I know it’s a slow drive by modern standards, but there’s plenty of RAM and both the CPU and drive are much faster than, say, on my iBook G3, which was never that slow to use.

Well, I've just played with various instructions to disable the console logging (or disable the logging of certain apps) but it looks like the whole system is so riddled with bugs that what's supposed to work does not actually work. Various additions to asl.conf just don't work as they should, and nor does creating specific config fies per app in the /etc/asl/ directory.

My references included the following:

http://apple.stackexchange.com/questions/168423/is-there-any-way-of-filtering-out-messages-from-os-x-system-log/272888#272888

and

http://apple.stackexchange.com/questions/157154/how-to-disable-logging-to-system-log-in-os-x

Apparently this might hold the truth:

http://apple.stackexchange.com/questions/168423/is-there-any-way-of-filtering-out-messages-from-os-x-system-log/272888#272888

... but I'm afraid I just don't know enough about these things to make sense of it.

Those seem to pertain to the old ASL system. The new one is os_log (WWDC session). There’s some documentation in the log.h header about how to configure it using files in the LogPreferences folder, but I haven’t tried that.

[…] Lloyd Chambers (via Michael Tsai): […]

@Michael I like how on the os_log page the link to "Customizing Logging Behavior While Debugging" goes nowhere because they clearly haven't written it yet :-)

@Keir I remember there being an in-depth Web page about os_log back when it was introduced and I was updating my code. But I can’t seem to find it with Google or Apple’s search now.

I'm really no idea if anybody is following this but I did some digging in the log man file, and found the following command will do the trick to stop logging of a particular app in macOS Sierra (you'll need to use pgrep to find the app/process PID and specify it):

sudo log config --process=PID --mode "level:off"

(Careful copying and pasting this – I suspect the comments system on this site might've converted the dashes and quotation marks).

So, you can manually find the PID for each process and kill it – or least for "noisy" apps/processes, I guess – or you can use a quick bash script to iterate through all PIDs up to, say, 6000 and turn off logging for all of them:

for i in {1..6000}
do
sudo log config --process=$i --mode "level:off"
done

Save it, make it executable, and run it with sudo itself.

This works. It's hacky, but it it works if you want to disable most logging. The script could do with error handling/trapping but as it stands you could feasibly turn this into an Automator action and add it to your user startup items.

I'll play around with this a bit longer and might write it up for my blog Mac Kung Fu. If anybody has any suggestions then I would love to hear them.

OK, last word on this I promise (even I'm getting bored).

There's also a SUBSYSTEM component for the "log config" command that at first glance promises to do away with the need for PIDs and silencing individual app/process logging.

Luckily the Krypted blog today published a list of these subsystems: http://krypted.com/mac-os-x/macos-logging-subsystems-gist/

Alas, it appears that you cannot turn off entire subsystems. Something like this doesn't appear to do anything:

sudo log config --subsystem Messages --mode "level:off"

I also stumbled across this page, which I think is the one Michael was referring to earlier. For those interested in silencing logging the latter half of the page is worth reading:

https://developer.apple.com/reference/os/logging?language=objc

I leave https://red-sweater.com/touche/ running and it makes the nowplayingtouchui log messages stop. The window doesn't need to be visible.

@Keir Yep, that’s the page.

It's a good point - what percentage of CPU time is being wasted by this?

Another point: This also makes it really hard to get users to help troubleshoot problems. No longer can you simply say: go to the console and copy the log lines from my app. Users MUST know how to use the filter to find anything useful.

Somewhat tangential, but may be helpful: Howard Oakley has written extensively about Sierra's new logging system, and has even written a Console replacement.

https://eclecticlight.co/tag/log/

@rjt Yes, it’s much harder for customers. Further complicating matters is that some of the log entries are not persisted to disk. So you can only see them if you had opened Console prior to the problem occurring.

Adam R. Maxwell

I used to keep Console.app open all the time on my Mac Pro running El Capitan, but after I found it using 10+ GB of RAM a few times and spinning on autorelease after running overnight, I gave up. All of my traditional HDD systems have been brutally slow since at least Yosemite, and my assumption is that Apple basically assumes swap is now as fast as RAM, and doesn't bother optimizing memory usage at all.

Sierra logs so much stuff that I don't even think about using Console anymore. Fortunately my own app (TeX Live Utility) has a console built in, so I can log NSTask output and anything else I want. This makes it a lot easier for users to copy the output and send it to me, and I also save the last few sessions.

@keir && @michael Regarding the slowness of maOS Sierra on hard drive, there could be another culprit:

https://www.reddit.com/r/applehelp/comments/5myyqk/what_it_is_applessdstatistics_and_why_is_reading/

I haven't tried it yet on an iMac that has become barely usable since OS X 10.11, but it sounds like a promising solution.

As mentioned I've outlined all the steps required to silence a runaway logging app over at my blog:

http://www.mackungfu.org/TurnoffrunawayloggingonmacOS

I've tried to make it as easy and accessible as possible.

Here's a script that'll turn off everything, checking whether a given pid exists before trying to squelch it.

#!/bin/bash

for i in {1..70000};
do
    NUM=`ps -o pid -p $i | grep $i `

    if [ $NUM ];
    then
	echo “ $i $NUM ”
	sudo log config --process=$i --mode 'level:off'
    fi
done

Unfortunately the commandline method here won't be very effective unless run when rebooting and periodically thereafter. And won't help with processes that restart periodically, check something, spew to the console, then quit.

Something that would work on process or executable names would be better.

@jon, terrific thanks for that. As far as I can see the log command only lets you specify a PID (although this is a young command – maybe in 10.13 it'll be better). Somebody could create a command that users could stick in /usr/bin that reads the process name as an input and then converts it to a PID for log killing – users could type something like "logkill touchid".

But really somebody needs to create a GUI app that shows you the log, lets you click a process and then kill/suspend its logging – and/or an app that runs in memory and periodically kills logging for any processes that kick-off. Or that monitors logging for runaway apps/processes and kills them automatically – maybe something like more than 100 log writes in 10 seconds means an automatic log kill.

I'm not an app developer. I'm just a computer journalist!

Having been playing with logging killing for a few days i can see two issues:

1. Like you say, some processes pop-up and then log prodigiously (apple.com.WebKit.WebContent/Networking, I'm looking at you), and then disappear. Some like webkit do this repeatedly, concurrently and massively.

2. There's no way to stop kernel level logging as far as I can see, and several other deep processes don't have user-accessible PIDs so can't be quieted – although these are well behaved in any event, so it's less necessary.

@Jon H, your script doesn't work for me. It seems "ps -o pid -p" isn't valid.

@Keir

Hm. Works for me. Did you use ` from the key with the tilde, or single quote '? It should be the backtick from the tilde key.

@Jon H, ah I see. I thought they were single quotes being smartified by the commenting software (the quotes later on appear to have been converted for example).

I'm experimenting at the moment with running Jon H's script every half hour to quell as much app/process logging as possible. I added a "sleep 0.05" command upon each iteration of the loop because otherwise the script starts to hog processing power, and the fans spin-up. To make it run every half hour it's via a launchd script.

I swear my MacBook Pro's battery life has improved. It's been working off battery and I haven't charged it all day. Right now at 8.30pm my time (UK) I'm down to 7%. Normally by this time I'd be back on the charger. I'm fully prepared to admit I might just be imagining the improvements, however.

As always if this is successful or useful I'll write it up at Mac Kung Fu.

"I'm experimenting at the moment with running Jon H's script every half hour to quell as much app/process logging as possible."

I assume that you've opened up Console, and the fire hose has been appropriately throttled?

@Chucky Well it started with Console spewing so, yes, that's what I check. You can also use the "log stream" command at the command line.

@Jon H
Why do you probe 70000 PIDs? The PS command returns a list of all PIDs.

pids=$(ps -e | grep -v -F 'PID' | awk '{print $1}')

for pid in $pids ; do
        sudo log config --process=$pid --mode 'level:off'
done

@Bamboo very nice, thanks!

As a side note, a Dropbox component is incompatible with the log-killing command (I forget which). If you attempt to turn off logging for that particular PID then the command just gets stuck, and won't proceed until you Ctrl+C to quit.

This is problematic for these looping log-killing commands because it halts them, leaving a bash process running, although with my launchd script that runs the loop in the background I've added a line (ExitTimeOut) that kills the launchd process after 15 minutes regardless of what happens.

This might be a bug with Apple or a Dropbox bug, or maybe both.

@Bamboo "Why do you probe 70000 PIDs?"

Because when I was writing it PIDs were up that high. Also, it was quick and dirty. I use ps to check for the existence of a process with a given PID but I don't use it to obtain a list of PIDs. I suppose a process could start or end between the time you obtain that list of PIDs from ps and the time the loop gets around to processing that PID.

[…] Previously: macOS 10.12.4 Locks Console Log Away From Normal Users, Sierra Logging Spew. […]

Just wanted to drop this here, there are still some logs being written it seems after using log config but this command will be far more efficient at getting all current PIDs and only running the command on them.

Break down of the command is: run with sudo, get all processes from every user, pipe through awk and return only second column which is the PID, then pipe each PID though xargs which passes it to the log config command.

sudo ps -alA | awk '{ print $2 }' | xargs -I 'log config --process=% --mode "level:off"'

Leave a Comment