1287156 - [10.12] Lots of time spent in syscall_thread_switch during arena_malloc, causing jank

Status: RESOLVED WORKSFORME

(Core :: Memory Allocator, defect)

Description

[Markus Stange [:mstange]]

Attachment: stack

Example profile: https://cleopatra.io/#report=daf2c09cc7775db9892148ab1ce2bca6ae3a1b6c

This has been happening on macOS 10.12 Beta 2 on Nightly ever since the startup hang (bug 1284677) has been fixed. It's not happening on Dev Edition / Beta / Release, and it's not happening on a local build with --disable-replace-malloc.

Steps to reproduce:
 1. Open Nightly on macOS 10.12 Beta 2.
 2. Open 20 empty tabs.
 3. Scroll the tab bar with your touchpad.

It's very janky. I think bug 1287109 and bug 1287114 are the same issue.

It looks like every invocation of arena_malloc takes around 100ms. syscall_thread_switch is how OSSpinLockLock yields to other threads.

I haven't checked whether the call to syscall_thread_switch itself takes 100ms, or if syscall_thread_switch is just called lots of times until the spinlock is released.

Using a debugger, I can easily break in syscall_thread_switch just by starting to scroll the tab bar and clicking XCode's pause button. Looking at "bt all", it doesn't seem like any other thread is doing memory allocation, so I'm not sure why the spin lock does anything at all.
I'm attaching a sample "bt all" output to this bug.

Comment 1

[Markus Stange [:mstange]]

Attachment: Activity Monitor sample of the same process

Comment 2

[Nathan Froyd [:froydnj]]

Can you get a profile with dtrace?  dtrace would be able to tell you if you were seeing lots of calls to syscall_thread_switch or lots of time inside syscall_thread_switch.

Comment 3

[Markus Stange [:mstange]]

Attachment: dtrace log

Good idea! Here's a log I generated with
sudo dtrace -n 'mach_trap::thread_switch:entry/pid == 57211/ { printf("%ums %d", timestamp / 1000 / 1000, tid); }'

Most of the calls complete within about 1µs (0.001ms), but some of them take around 100ms. Here's an excerpt with two ~100ms events:

  2    125              thread_switch:entry 5350363ms 7222204
  0    125              thread_switch:entry 5350363ms 2201240
  0    125              thread_switch:entry 5350363ms 2201240
  4    125              thread_switch:entry 5350465ms 2201240 <-- + 98ms
  0    125              thread_switch:entry 5350567ms 7222204 <-- + 102ms
  0    125              thread_switch:entry 5350567ms 7222204
  0    125              thread_switch:entry 5350567ms 7222204
  0    125              thread_switch:entry 5350567ms 7222204
  0    125              thread_switch:entry 5350567ms 7222204

Comment 4

[Markus Stange [:mstange]]

mach_trap::thread_switch:return is never triggered, only :entry is.

Comment 5

[Markus Stange [:mstange]]

I filed an Apple bug about this today.

Comment 6

[Markus Stange [:mstange]]

This has been fixed in Beta 6!