AppleScript Safari "do JavaScript" command is extremely slow in Big Sur

Since upgrading to Big Sur, sending AppleScript "do JavaScript" command to Safari runs extremely slowly.

For example:
Code Block
tell application "Safari"
set rslts to do JavaScript "document.title;" in document 1
end tell

... this used to take a split second in prior versions of the MacOS. Since upgrading to Big Sur, running this script results in a spinning pinwheel, the Safari's CPU usage ramps up to 100% and the command takes about 10 seconds to complete.

Answered by ForumsContributor in
Weird. I do this all the time on my main Mac and I never see that sort of delay. You should definitely file a bug about that, making sure to include a sysdiagnose log taken shortly after reproducing the problem.

For more information about sysdiagnose logs, see our Bug Reporting > Profiles and Logs page.

Please post your bug number, just for the record.

I have a quick diagnostic test for you to run, namely, create a new user, log out of your current user, log in as that user, and then try reproducing the problem. This will tell you whether this is a problem with your machine as a whole or your specific user.

Share and Enjoy

Quinn “The Eskimo!” @ Developer Technical Support @ Apple
let myEmail = "eskimo" + "1" + "@" + "apple.com"
Thanks for the suggestion. Indeed it's the user, not the machine, nor the OS. Thanks for the clarification. I'm assuming there are some users settings or preferences to delete to fix this?

Indeed it's the user

OK, that’s a very useful data point.

I'm assuming there are some users settings or preferences to delete to
fix this?

Indeed, but I’ve no idea what that might be )-: Normally a very long delay like this is not caused by things running slowly but rather by things not running at all, that is, things being blocked waiting for some event to occur, like a network operation. In this case, however, you mentioned that:

Safari's CPU usage ramps up to 100%

which suggests the opposite. Try this:
  1. Use Activity Monitor to see which Safari process is burning all that CPU.

  2. Then sample that process (select it and choose Sample Process from the action menu) to see what it’s doing.



Oh, and btw, please file a bug about this, because clearly something has gone very wrong. Attach a sysdiagnose log to your bug. You can generate one by the same process as above, except choosing System Diagnostics from the action menu.

Please post your bug number, just for the record.

Share and Enjoy

Quinn “The Eskimo!” @ Developer Technical Support @ Apple
let myEmail = "eskimo" + "1" + "@" + "apple.com"
Thanks @eskimo

OK followed up on your suggestions -- sent in a Bug report and have a tech support for it as well. Will follow up when I hear back.

RE

Try this:
Use Activity Monitor to see which Safari process is burning all that CPU.
Then sample that process (select it and choose Sample Process from the action menu) to see what it’s doing.

Tried that in 2 ways:
1 - Watching Safari's subprocesses with Activity Monitor set to View > All processes, hierarchically.
Only the master app, "SafarI" runs at 100%. All the sub-processes remain around 1% or so..

2 - Sampling Safari while simultaneously running the AppleScript.
Returns a mountain of data, but I don't know how to make sense of it yet. LMK if you have any clues what to look for.


Returns a mountain of data, but I don't know how to make sense of it
yet.

The trick here is to look at each thread and see where it’s spending time.

The way that this sample works is that it periodically stops the process and backtraces each thread. It then merges these backtraces into a tree with counts. So, for example, consider this:

Code Block
2529 Thread_48405 DispatchQueue_1: com.apple.main-thread (serial)
+ 2529 start …
+ 2529 SafariMain …
+ 2529 NSApplicationMain …
+ 2516 -[NSApplication run] …
+ ! 2516 -[BrowserApplication nextEventMatchingMask:untilDate:in…
+ ! 2506 -[NSApplication(NSEvent) _nextEventMatchingEventMask:…
+ ! : 2505 _DPSNextEvent …
+ ! : | 2505 _BlockUntilNextEventMatchingListInModeWithFilter …
+ ! : | 2494 ReceiveNextEventCommon … + 587 …
+ ! : | 11 ReceiveNextEventCommon … + 284 …


This shows that the main thread was sampled 2529 times and:
  • All 2529 backtraces included NSApplicationMain (duh!).

  • Only 2516 included -[NSApplication run].

  • But all of those also included -[BrowserApplication nextEventMatchingMask:untilDate:inMode:dequeue:].

I’ve heavily edited this to highlight the area around _BlockUntilNextEventMatchingListInModeWithFilter. Of the 2529 total backtraces, 2505 included that symbol. And of those, 2494 included ReceiveNextEventCommon + 587 and the remaining 11 included ReceiveNextEventCommon + 284.

The next key factoid is to understand blocking points. Here’s another snippet from the same sample:

Code Block
2529 Thread_48405 DispatchQueue_1: com.apple.main-thread (serial)
+ 2529 start …
+ 2529 SafariMain …
+ 2529 NSApplicationMain …
+ 2516 -[NSApplication run] …
+ ! 2516 -[BrowserApplication nextEventMatchingMask:untilDate:in…
+ ! 2506 -[NSApplication(NSEvent) _nextEventMatchingEventMask:…
+ ! : 2505 _DPSNextEvent …
+ ! : | 2505 _BlockUntilNextEventMatchingListInModeWithFilter …
+ ! : | 2494 ReceiveNextEventCommon …
+ ! : | + 2494 RunCurrentEventLoopInMode …
+ ! : | + 2494 CFRunLoopRunSpecific …
+ ! : | + 2492 __CFRunLoopRun …
+ ! : | + ! 2492 __CFRunLoopServiceMachPort …
+ ! : | + ! 2492 mach_msg …
+ ! : | + ! 2492 mach_msg_trap …


Looking at this you might think “Gosh, mach_msg_trap is using a lot of CPU!”, but that’s not the case. mach_msg_trap is a blocking routine; it’s where the run loop goes when it’s waiting for an event to occur, and it blocks waiting for that next event. So, having it show up in a lot of samples is typically a good thing. It tells you that the thread was mostly most blocked waiting for events.

If you survey the threads in Safari you’ll see that a bunch of them spend most of their time blocked in routines like this. What you’re looking for is the thread, or threads, that are not blocked like this, for example:
  • The samples for the thread are scattered around a bazillion different routines.

  • The samples are concentrated in one routine, or a small set of them, but they are obviously not blocking.

You can then look at the backtraces to see if you can work out what that thread was doing.

Share and Enjoy

Quinn “The Eskimo!” @ Developer Technical Support @ Apple
let myEmail = "eskimo" + "1" + "@" + "apple.com"
Thank you for the detailed explanation. There's a lot that I'm not quite following yet.

This shows that the main thread was sampled 2529 times and:
All 2529 backtraces included NSApplicationMain (duh!).
Only 2516 included -[NSApplication run].
But all of those also included -[BrowserApplication nextEventMatchingMask:untilDate:inMode:dequeue:].
I’ve heavily edited this to highlight the area around _BlockUntilNextEventMatchingListInModeWithFilter. Of the 2529 total backtraces, 2505 included that symbol. And of those, 2494 included ReceiveNextEventCommon + 587 and the remaining 11 included ReceiveNextEventCommon + 284.

What's the implication of a larger number -- "2494 ReceiveNextEventCommon" -- followed by the smaller number "11 ReceiveNextEventCommon"

What you’re looking for is the thread, or threads, that are not blocked like this, , for example:
The samples for the thread are scattered around a bazillion different routines.
The samples are concentrated in one routine, or a small set of them, but they are obviously not blocking.

I'm imagining a listing that, instead of being hierarchical is more or less flat, repeating over and over again. Is that what you mean?

When you say "blocked" and "not blocked" I'm in a JavaScript headspace where synchronous block the next command and asynchronous step aside and let the next steps run, but that might be misunderstanding what you're getting at.


What's the implication of a larger number -- 2494 ReceiveNextEventCommon

  • - followed by the smaller number

11 ReceiveNextEventCommon
It means that all 2505 of that thread’s backtraces that included _BlockUntilNextEventMatchingListInModeWithFilter also included ReceiveNextEventCommon, but not all of them were at the same site within ReceiveNextEventCommon. Imagine an implementation of ReceiveNextEventCommon that looks like this:

Code Block
on ReceiveNextEventCommon
while true
event = RunCurrentEventLoopInMode
DoSomethingWithEvent(event)
end while
end


2494 of the backtraces included RunCurrentEventLoopInMode and 11 included DoSomethingWithEvent (note that I’m making up that symbol name because I don’t have access to the sample I took yesterday). This is pretty much what I’d expect. Most of the backtraces run through RunCurrentEventLoopInMode because that blocks waiting for the next event. Some run through DoSomethingWithEvent as the program processes the events that it received.

I'm imagining a listing that, instead of being hierarchical is more or
less flat, repeating over and over again. Is that what you mean?

Well, there’s two common modes:
  • The program might be running a complex framework, in which case there will be a complex forest of trees with none of the leaf nodes being particularly heavy.

  • The program might be stuck inside a computation loop, where there’s a single very heavy leaf node.

The key thing is that there’s obviously no blocking leaf node, like mach_msg_trap.

When you say "blocked" and "not blocked" I'm in a JavaScript headspace
where synchronous block the next command and asynchronous step aside
and let the next steps run

JavaScript is a bit weird because it doesn’t have threads (some might argue that’s a good thing :-). So all long-running operations must necessarily be async (either with callbacks or async/await). If you did a long-running operation sync, you’d lock up the entire JavaScript engine for the duration O-:

Native code supports threads, which means that, for better or worse, sync operations are possible. For example, in BSD Sockets, if you do a read on a socket, it won’t return until it gets some data or gets an error.

To support this efficiently the system must implement the notion of blocking. The code can’t spin in a loop waiting for network data to arrive because that burns through CPU and battery. Rather, the system blocks the thread and then unblocks it when something interesting happens.



Taking a step back, if you poste a copy of your sample I’d be happy to take a look. Use the text attachment feature (the paperclip icon) to avoid clogging up the timeline.

Share and Enjoy

Quinn “The Eskimo!” @ Developer Technical Support @ Apple
let myEmail = "eskimo" + "1" + "@" + "apple.com"

Native code supports threads... To support this efficiently... the system blocks the thread and then unblocks it when something interesting happens.

Interesting. Thanks for that.

Taking a step back, if you poste a copy of your sample I’d be happy to take a look. Use the text attachment feature (the paperclip icon) to avoid clogging up the timeline.

Thanks for that. I tested some samples the other day after reading your notes. I got as far as getting an inkling, so your offer is very much appreciated.





Accepted Answer
Thanks for the sample. Let’s focus on Safari’s main thread for the moment. I’ve rewritten the ‘heavy’ path of the main thread’s sample tree into a traditional backtrace:

Code Block
0 ***::RunLoop::cycle(__CFString const*) (in JavaScriptCore) + 22 [0x7fff3751bbf6]
1 Inspector::RemoteInspectionTarget::pauseWaitingForAutomaticInspection() (in JavaScriptCore) + 40 [0x7fff36…
2 JSC::JSGlobalObjectDebuggable::pauseWaitingForAutomaticInspection() (in JavaScriptCore) + 42 [0x7fff371973…
3 Inspector::RemoteInspector::updateAutomaticInspectionCandidate(Inspector::RemoteInspectionTarget*) (in Java…
4 JSGlobalContextCreateInGroup (in JavaScriptCore) + 169 [0x7fff364cbc69]
5 std::__1::__function::__func<-[BrowserWKView handleDoJavaScriptCommand:]::$_0, std::__1::allocator<-[Browser…
6 Safari::WK::Page::runJavaScriptInMainFrame(NSString*, std::__1::function<void (Safari::WK::SerializedScriptV…
7 *::Detail::CallableWrapper<WebKit::WebPageProxy::runJavaScriptInFrameInScriptWorld(WebCore::RunJavaScriptP…
8 Messages::WebPage::RunJavaScriptInFrameInScriptWorld::callReply(IPC::Decoder&, *::CompletionHandler<void (…
9 *::Detail::CallableWrapper<void IPC::MessageSender::sendWithAsyncReply<Messages::WebPage::RunJavaScriptInF…
10 *::Detail::CallableWrapper<WebKit::AuxiliaryProcessProxy::sendMessage(std::__1::unique_ptr<IPC::Encoder, s…
11 IPC::Connection::dispatchMessage(std::__1::unique_ptr<IPC::Decoder, std::__1::default_delete<IPC::Decoder> >…
12 IPC::Connection::dispatchIncomingMessages() (in WebKit) + 488 [0x7fff3c0e9aa6]
13 *::RunLoop::performWork() (in JavaScriptCore) + 573 [0x7fff3751a9ed]
14 *::RunLoop::performWork(void*) (in JavaScriptCore) + 26 [0x7fff3751b75a]
15 __CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__ (in CoreFoundation) + 17 [0x7fff20668a8c]
16 __CFRunLoopDoSource0 (in CoreFoundation) + 180 [0x7fff206689f4]
17 __CFRunLoopDoSources0 (in CoreFoundation) + 242 [0x7fff20668774]
18 __CFRunLoopRun (in CoreFoundation) + 893 [0x7fff2066719c]
19 CFRunLoopRunSpecific (in CoreFoundation) + 563 [0x7fff2066675c]
20 RunCurrentEventLoopInMode (in HIToolbox) + 292 [0x7fff28888203]
21 ReceiveNextEventCommon (in HIToolbox) + 587 [0x7fff28887f65]
22 _BlockUntilNextEventMatchingListInModeWithFilter (in HIToolbox) + 70 [0x7fff28887d03]
23 _DPSNextEvent (in AppKit) + 864 [0x7fff22e62b32]
24 -[NSApplication(NSEvent) _nextEventMatchingEventMask:untilDate:inMode:dequeue:] (in AppKit) + 1364 [0x7fff…
25 -[BrowserApplication nextEventMatchingMask:untilDate:inMode:dequeue:] (in Safari) + 231 [0x7fff43c7a257]
26 -[NSApplication run] (in AppKit) + 586 [0x7fff22e53679]
27 NSApplicationMain (in AppKit) + 816 [0x7fff22e2785c]
28 SafariMain (in Safari) + 448 [0x7fff43c63f60]
29 start (in libdyld.dylib) + 1 [0x7fff2058af3d]


So, frames 29…15 are the standard stuff you’d see at the top of any Mac app. The app has called NSApplicationMain which is then running the run loop dispatching events.

Frame 14…9 represent a WebKit-specific event handler. Some work has come in over an IPC channel and it’s doing that work.

Frame 8 suggests that this work is your do JavaScript command.

Frames 5…0 are where things get interesting. It seems that something is triggering the Inspector, which has then blocked the thread waiting for it to attach (frames 1 and 0).

I suspect that the Inspector in this case is the Web Inspector, but that’s basically a guess. I don’t know the WebKit / JavaScriptCore source code well enough to tell you for sure.

Having said that, those technologies are both open source, so you could go look it up for yourself (-: Or you could escalate this via their support resources.

Before you do that, however, you should check your Develop menu to see if you have accidentally set something that might trigger this (-: For example, Developer > My Mac Name > Automatically Show Web Inspector for JSContexts and Automatically Pause Connecting to JSContexts seems suspiciously apropos.

Share and Enjoy

Quinn “The Eskimo!” @ Developer Technical Support @ Apple
let myEmail = "eskimo" + "1" + "@" + "apple.com"

Developer > My Mac Name > Automatically Show Web Inspector for JSContexts

This nailed it. Brilliant.

But actually all the other stuff you ended up explaining is really interesting and helpful. It'll take some time to get a handle on it, but very much appreciate all your help.

SOLVED. Thank you!
AppleScript Safari "do JavaScript" command is extremely slow in Big Sur
 
 
Q