Active Directory bind, opendirectoryd, and indentitysvc()
Active Directory bind, opendirectoryd, and indentitysvc()
- Subject: Active Directory bind, opendirectoryd, and indentitysvc()
- From: Jon Shier <email@hidden>
- Date: Wed, 18 Jul 2012 16:47:06 -0400
Kernel List:
In attempting to diagnose a delay seen on 10.7.4 systems when initially binding to an AD domain (System Preferences dialog show "Updating search paths..." for 30 seconds every time) and on every reboot (login window displays "Network accounts unavailable" for up to 30 seconds before becoming available), I believe I've tracked the issue to opendirectoryd waiting on the identitysvc() syscall to return from the kernel. A "sample" of opendirectoryd during binding and a dtruss analysis shows that opendirectoryd is waiting and that the identitysvc() syscall is responsible. Here is the dtruss output, sorted by overall time spent in a call. There are also calls to poll() and kevent(), which I'm assuming are normal. (Please excuse the formatting.)
| PID/THRD |
RELATIVE |
ELAPSD |
SYSCALL(args) |
| 17/0x13e: |
74362 |
26590056 |
identitysvc(0x2, |
| 17/0xd3bef: |
49 |
23523715 |
poll(0x7FC67186BC18, |
| 17/0xd3bf4: |
68 |
9971586 |
poll(0x7FC671873E18, |
| 17/0xd3bf4: |
2793 |
8215867 |
poll(0x7FC671873E18, |
| 17/0x13a: |
31311289 |
2000747 |
kevent(0x3, |
| 17/0x13a: |
31317710 |
2000087 |
kevent(0x3, |
| 17/0x13a: |
31315540 |
1999916 |
kevent(0x3, |
| 17/0x13a: |
31312691 |
1999789 |
kevent(0x3, |
| 17/0x13a: |
31311237 |
1999768 |
kevent(0x3, |
| 17/0x13a: |
31316199 |
1999716 |
kevent(0x3, |
| 17/0x13a: |
31317636 |
1998941 |
kevent(0x3, |
| 17/0x13a: |
31316132 |
1951744 |
kevent(0x3, |
| 17/0xd3bf4: |
520 |
1749670 |
poll(0x7FC671873E18, |
| 17/0x13a: |
31310248 |
1598006 |
kevent(0x3, |
| 17/0x13a: |
31311937 |
1550393 |
kevent(0x3,
|
As you can see, opendirectoryd is spending 26.59 seconds waiting for the identitysvc() syscall to return. This matches exactly the delay seen on binding. I further investigated the issue by using dtrace to to follow opendirectoryd's identitysvc() syscall into the kernel. This trace shows the following pattern, followed by various thread calls, occurs consistently until the syscall returns.
1 => identitysvc fd: 2
1 -> identitysvc
1 -> lck_mtx_lock
1 <- lck_mtx_lock
1 -> msleep0
1 -> assert_wait_deadline
1 <- assert_wait_deadline
1 -> lck_mtx_unlock_darwin10
1 <- lck_mtx_unlock_darwin10
1 -> thread_should_abort
1 <- thread_should_abort
1 -> thread_block
1 -> thread_block_reason
1 -> can_update_priority
1 <- can_update_priority
1 -> choose_thread
1 <- choose_thread
1 -> thread_timer_event
1 <- thread_timer_event
1 -> stack_handoff
1 -> fpu_save_context
Followed by this pattern:
-> unix_syscall64
1 -> kauth_cred_uthread_update
1 <- kauth_cred_uthread_update
1 -> identitysvc
1 -> lck_mtx_lock
1 <- lck_mtx_lock
1 -> msleep0
1 -> assert_wait_deadline
1 <- assert_wait_deadline
1 -> lck_mtx_unlock_darwin10
1 <- lck_mtx_unlock_darwin10
1 -> thread_should_abort
1 <- thread_should_abort
1 -> thread_block
Until the call returns:
-> unix_syscall64
1 -> kauth_cred_uthread_update
1 <- kauth_cred_uthread_update
1 -> identitysvc
1 -> lck_mtx_lock
1 <- lck_mtx_lock
1 -> lck_mtx_unlock_darwin10
1 <- lck_mtx_unlock_darwin10
1 <- identitysvc
1 <= identitysvc
Am I on track here? Is this behavior normal? In looking at the source for the identitysvc() syscall, I noticed that a few of the related functions have a 30 second timeout in some scenarios, which matches my observed behavior almost exactly. Is there a way to enable the kauth debug logging without recompiling the kernel? Any other dtrace recommendations for gather more information? Is anyone familiar with the opendirectory probes for dtrace? Perhaps they could shed more light.
Thanks,
Jon Shier
_______________________________________________
Do not post admin requests to the list. They will be ignored.
Darwin-kernel mailing list (email@hidden)
Help/Unsubscribe/Update your Subscription:
This email sent to email@hidden