Multi-CPU Binding in Solaris

We are working on a framework which would allow processes/thread to have affinity to more than one CPU. The affinities could be divided into three categories -- (a) strong affinity (b) weak affinity and (c) negative affinity.

(a) strong affinity :- This type of affinity would allow processes/threads to run only on specified CPUs.

(b) weak affinity :- This type of affinity would allow processes/threads to run on its home lgroup or CPUs specified or any CPUs if it can't run on home lgroup/CPUs. The order is also followed in the same way when Solaris Dispatcher would choose a CPU.

(c) negative affinity :- This type of affinity would allow processes/threads to not run on the CPUs specified.

At present, only strong/negative affinity could change thread's home lgroup; so on a NUMA aware machine, users need to be more cautious. These affinity are stored in bitmask of CPUs (cpuset_t). During offline phase, CPU will be removed from thread's bitmask and if it happens to be the only CPU in its bitmask, we would generate an event using contract fs so that application programs can take appropriate action in an event when affinity is revoked during offline or even when a CPU goes out from processor set.

The boundaries laid by CPU partitions will still be there and Multi-CPU binding will not allow processes/threads to cross partitions (or proessesor sets).

Idle thread is also modified to accordingly look for work. Strong affinity threads can't be stolen if a thread doesn't have that CPU in its bitmask. Weak affinity threads can be stolen. Run queue balancing done by setbackdq() is done for all the affinities.

An example of it :-

bash-3.00# ./pbind -s 528-530 `pgrep aff`

bash-3.00# dtrace -s ./a.d ## D script capturing context switches.
CPU no. of times ran
529 197
528 208
530 210

bash-3.00# ./pbind -q `pgrep aff`
process id 3211: not bound
process id 3211: strong affinity to: 528-530

bash-3.00# psradm -f 529 528

bash-3.00# dtrace -s ./a.d ## D script capturing context switches.
CPU no. of times ran
530 255


If you were to offline CPU 530 also, this would cause us to revoke the affinities because this process had strong affinity and there wouldn't be any CPU where it can run. The purpose is to allow offline (for DR or other FMA events). Same hold true for processor set as well if a CPU is removed from the pset and it happens to be be last CPU in the threads CPU bitmask.

We can preserve affinity to a CPU when a CPU is offlined so that when it is brought back users don't have to bother about finding a suitable CPU provided it's not the last CPU in its bitmask. I'm not sure whether it would be good or do we really want to do this. I do have a prototype based on that.

The above demo is just for what we are trying to achive and it's in the prototyping stage.

VFS/Vnode Layer in Solaris

In past I have mostly written on dispatcher locks (thread locks), scheduler, signal, procfs. This is for the first time, I'm writing about filesystem. I hope it'll help you in increasing awareness on filesystem so that developing filesystem specific things on Solaris is made easy.

In this blog, I'll dessribe about how to implement VFS (Virtual Filesystem) Layer and Vnode layer for any filesystem. There are two ways you can read disk data :-

(a) using buffer cache : bread() is used to read a block of the device. The block number is always with respect to the device. brelse() must be called once buffer data is read from buf_t->b_un.b_addr

(b) using segmap driver and setting up the pages.

Using VFS layer, we can export following filesystem operations :-

(a) mount : In this operation, we need to first see whether device can be mounted or not. We also need to read the super-block (depending upon whether it's primary partition or logical partition). We are required to create pseudo device also using following calls

pseudodev = makedevice(getmajor(xdev), minor); // xdev is the device passed to mount(1m) devvp = makespecvp(xdev, VBLK); // devvp is used to do reads

Once the pseudo device is created, we open the device to read super-block and check the filesystem signature. This information is copied to in-core super-block. Now comes the hard work to mount the filesystem. Here we get the vnode for the mount point and mark it VROOT (vp->v_flag). The VFS structure is also filled. For instance vfs_data will have pointer to fs structure (struct ufsvfs) which will have super-block and other general other information about the filesystem. VFS layer routines takes care of adding vfs structure to the global array 'vfssw' of struct vfssw type.

(b) unmount : This operation is very critical. Unmount should not go through while processes are inside the mount point unless -f (force flag is passed to umount(1m)). We need to maintain the reference count so that we don't allow unmount to go through while process's current working directory is inside the mount point. For this we can increment the reference count whenever vnode is allocated and decrement it whenever vnode is released via VOP_INACTIVE(). Hence xxx_unmount() operation should first check whether it's safe to unmount the filesystem or not. DNLC will be purged by VFS layer routines before we land in filesystem specific unmount operation.

(c) stat on the filesytem : df(1m) calls stat for each mount point. In this operations, we are required to return following information in statvfs64 structure :

f_bsize    // block size
f_frsize   // block size. UFS has fragment size to accomodate small files.
f_blocks   // total number of blocks in the filesystem
f_bfree    // free blocks
f_files = (fsfilcnt64_t)-1;
f_ffree = (fsfilcnt64_t)-1;
f_favail = (fsfilcnt64_t)-1;
f_fsid     // filesystem id
(void) strcpy(sp->f_basetype, vfssw[vfsp->vfs_fstype].vsw_name);   // name
f_flag = vf_to_stf(vfsp->vfs_flag);   // flag
f_namemax            // MAX filename size.

(d) sync operation : For read-only filesystem, we don't need to implement sync. Otherwise, it's used for flushing dirty pages in the filesystem.

(e) root operation : used by filesystem lookups to determine the root (or mount point). We are required to hold the vnode.

Vnode layer exports following operations. We will focus on operations which are required to support read operations on the filesystem. Write operations are very tricky as you need to implement host of other operations and locking the filesystem.

(a) read : This operation is invoked whether read(2) is called. In this routine, we use segmap to read the data of the file. We force fault the pages using

segmap_getmapflt(segkmap, vp, (off + mapon), , 1, S_READ);

and then uiomove is called to copy back to userland. We also release the smp (segmap entry) using segmap_release() once uiomove() is done. Please note that segmap uses 8192 (MAXBSIZE), so according you're required to manage the offset (off) and mapon which are calculated as :

off = uoff & (offset_t)MAXBMASK; mapon = (u_offset_t)(uoff & (offset_t)MAXBOFFSET);

(b) getattr : In this operation, we need to return 'vattr' struture. 'ls -l' read this struture. Following members are relvant here :-

va_type   // type of vnode
va_mode   // mode
va_uid    // uid
va_gid     // gid
va_atime.tv_sec // access time
va_mtime.tv_sec    // modification time
va_ctime.tv_sec    // creation time
va_size     // size
va_nlink    // link count
va_blksize  // block size
va_nblocks  // number of blocks

(c) lookup : This is the heart of any filesystem. We must provide lookup in the filesystem before we can read files or seach in a directory. This routine understands the filesystem structure. In this operation, you can also use DNLC (Directory name lookup cache) to enhance the fs lookup. The Vnode and name will be cached and we don't to go to the disk all the time to search for a file/directory. dnlc_enter() can be used to put an entry in DNLC and dnlc_lookup() can be used to search whether vnode can be found in DNLC given the name. Both the routines increment v_count using VN_HOLD().

(d) getpage_miss/getpage : This routine will read the block of a file given the offset. Here we need to setup the page using page_create_va() and prepare for reading the block data using pageio_setup(). In order to issue the IO, we do following things in order -- bdev_strategy(), biowait() and then pageio_done(). In order to support read-ahead, we can use pvn_read_kluster() routines. Filesystem specific getpage() routine will call getpage_miss() to read the block. In getpage(), we also do page_lookup() in order to save going to disk if page is already there in memory.

(e) readdir : This operation is used to read the directory entries. uio_offset passed in uio struture is the key thing here. If uio_offset is same as the filesize, then we have read all the directory entries. If that's not the case, then we read directory entries starting from the last offset which is passed to us in uio_offset. At the end, we are required to return the new offset in uio_offset, so that next time when readdir() is call again, we can read more directory entries.

There are host of other functions which are required when write is also supported on the filesystem. For instance putpage, write etc. In order to support mmap(), we need to use segvn segment driver instead of segmap.

Dispatcher locks and Bug 5017148

As part of the opensolaris release, I'm going to describe about the dispatcher locks, thread locks and a bug which I root-caused last year. The investigation didn't take much time, but it was an interesting one because door does magic in the kernel at the time of handoff to other thread (client to server or server to client). So let me begin with what's a dispatcher lock:

1. What's a dispatcher lock

Dispatcher lock is a one byte lock (disp_lock_t) which is acquired at high pil (DISP_LEVEL) and DISP_LEVEL is the interrupt level at which dispatcher operations should be performed. There are other symbolic interrupt levels viz. CLOCK_LEVEL and LOCK_LEVEL in machlock.h

Following are the interfaces for dispatcher lock which are described in disp_lock.c

disp_lock_init() initializes dispatcher lock.
disp_lock_destroy() destroys dispatcher lock.
disp_lock_enter() acquires dispatcher lock.
disp_lock_exit() releases dispatcher lock and checks for kernel preemption.
disp_lock_exit_nopreempt() releases dispatcher lock without checking for kernel preemption.
disp_lock_enter_high() acquires another dispatcher lock when the thread is already holding a dispatcher lock.
disp_lock_exit_high() releases the top level dispatcher lock.

Here are the facts about dispatcher locks :-

(a) Being a spin lock which are acquired at high level, dispatcher locks should be acquired for a short duration and shouldn't make blocking calls.
(b) While releasing dispatcher lock, you can be preempted if cpu_kprunrun (kernel preemption) is set. You can use disp_lock_exit_nopreempt() if you don't want to be preempted.
(c) While holding dispatcher lock, you are not preemptible.
(d) Since dispatcher lock raises pil to DISP_LEVEL, the old pil is saved in t_oldspl of the thread structure (kthread_t)

2. What's a thread lock

Thread lock is a per-thread entity which protects t_state and state-related flags of a kernel thread. Thread lock hangs off kthread_t as t_lockp. t_lockp is a pointer to thread dispatcher lock and the pointer is changed whenever the state of the kernel thread is changed. One would acquire thread lock using thread_lock() routine giving the kernel thread pointer. thread_lock() is responsible for getting the correct dispatcher lock for the thread. The dance done by thread_lock() is interesting because t_lockp is pointer and can get changed during the course of spinning for a dispatcher lock. Hence thread_lock() saves t_lockp pointer and ensures that we acquire the right thread lock.

Now lets take a look at the interfaces in Solaris kernel which are described in disp_lock.c and thread.h

thread_lock() is called to require thread lock.
thread_unlock() is called to release thread lock and it checks for kernel preemption.
thread_lock_high() is called to acquire another thread lock while holding one.
thread_unlock_high() is called to release thread lock while holding one.
thread_unlock_nopreempt() is called to release thread lock without checking for kernel preemption.

3. Various types of thread locks in Solaris Kernel

Now that I've described about thread lock, it's very important for us to understand what dispatcher locks are acquired depending upon the state of the thread. In order to find out this, you need to first understand the one-to-one mapping between the state of the thread and it's corresponding dispatcher lock:

TS_RUN (runnable) ---> disp_lock of the dispatch queue in a CPU (cpu_t) or global preemption queue of a CPU partition
TS_ONPROC (running ) ---> cpu_thread_lock in a CPU (cpu_t)
TS_SLEEP (sleep) ---> sleepq bucket lock or turnstile chain lock
TS_STOPPED (stopped) ---> stop_lock (a global dispatcher lock) for stopped threads.

There're two global dispatcher locks: shuttle_lock and transition_lock in Solaris Kernel. When thread lock of a thread is pointing to shuttle_lock, it means that the thread is sleeping on a door and when thread lock points to transition_lock, it means that thread is in transition to another state (for instance when the state of the thread sleeping on a semaphore is changed from TS_SLEEP to TS_RUN or during yield()). transition_lock is always held and is never released.

4. Examples of thread lock

Now lets understand what all thread locks will be involved from wakeup (or unsleep) to onproc (running) of a thread. Lets assume that T1 (thread 1) is blocked on a condition variable CV1 and T2 (thread 2) signals T1 as part of wakeup. First cv_signal() grabs sleepq bucket lock and decrements the waiters count on CV1. It then calls sleepq_wakeone_chan() to wakeup T1. sleepq_wakeone_chan()'s responsibility is to unlink T1 from the sleepq list (using t_link of kthread_t) and calls CL_WAKEUP (scheduling class specific wakeup routine). Assuming T1 is in time sharing class (TS), ts_wakeup() gets called. Now ts_wakeup() which in turn calls dispatcher enqueue routine (setfrontdq() or setbackdq()) changes the state of T1 thread to TS_RUN and changes t_lockp to point to disp_lock of the chosen CPU. At last sleepq_wakeone_chan() drops disp_lock of the dispatch queue and finally sleepq dispatcher lock is also released in cv_signal(). Once T1 is chosen to run, disp() removes T1 from the dispatch queue of the CPU and changes the state to TS_ONPROC and t_lockp to cpu_thread_lock of the CPU.

void
cv_signal(kcondvar_t *cvp)
{
       condvar_impl_t *cp = (condvar_impl_t *)cvp;

       /* make sure the cv_waiters field looks sane */
       ASSERT(cp->cv_waiters <= CV_MAX_WAITERS);
       if (cp->cv_waiters > 0) {
               sleepq_head_t *sqh = SQHASH(cp);
               disp_lock_enter(&sqh->sq_lock);
               ASSERT(CPU_ON_INTR(CPU) == 0);
               if (cp->cv_waiters & CV_WAITERS_MASK) {
                       kthread_t *t;
                       cp->cv_waiters--;
                       t = sleepq_wakeone_chan(&sqh->sq_queue, cp);
                       /*
                        * If cv_waiters is non-zero (and less than
                        * CV_MAX_WAITERS) there should be a thread
                        * in the queue.
                        */
                       ASSERT(t != NULL);
               } else if (sleepq_wakeone_chan(&sqh->sq_queue, cp) == NULL) {
                       cp->cv_waiters = 0;
               }
               disp_lock_exit(&sqh->sq_lock);
       }
}

The second example is from the phase of preemption. We know that there are two types of preemption in Solaris kernel viz. user preemption (cpu_runrun) and kernel preemption (cpu_kprunrun). Assume that T1 is being preempted in favour of a high priority thread. As a result T1 will call preempt() once T1 realizes that it has to give up the CPU (there're hooks in Solaris kernel to determine this). preempt() first grabs thread lock effectively cpu_thread_lock on itself and calls THREAD_TRANSITION() to change the t_lockp to transition_lock. Note that the state of T1 is still TS_ONPROC while t_lockp is pointing to transition_lock, because T1 is in transition phase (from TS_ONPROC -> TS_RUN). THREAD_TRANSITION() also releases previous dispatcher lock because transition_lock is always held. preempt() then calls CL_PREEMPT(), scheduling class specific preemption routine, to enqueue T1 on a particular CPU. From here on it's same as described in the first example.

void
preempt()
{
       kthread_t       *t = curthread;
       klwp_t          *lwp = ttolwp(curthread);

       if (panicstr)
               return;

       TRACE_0(TR_FAC_DISP, TR_PREEMPT_START, "preempt_start");

       thread_lock(t);

       if (t->t_state != TS_ONPROC || t->t_disp_queue != CPU->cpu_disp) {
               /*
                * this thread has already been chosen to be run on
                * another CPU. Clear kprunrun on this CPU since we're
                * already headed for swtch().
                */
               CPU->cpu_kprunrun = 0;
               thread_unlock_nopreempt(t);
               TRACE_0(TR_FAC_DISP, TR_PREEMPT_END, "preempt_end");
       } else {
               if (lwp != NULL)
                       lwp->lwp_ru.nivcsw++;
               CPU_STATS_ADDQ(CPU, sys, inv_swtch, 1);
               THREAD_TRANSITION(t);
               CL_PREEMPT(t);
               DTRACE_SCHED(preempt);
               thread_unlock_nopreempt(t);

               TRACE_0(TR_FAC_DISP, TR_PREEMPT_END, "preempt_end");

               swtch();                /* clears CPU->cpu_runrun via disp() */
       }
}

5. An example of a dispatcher lock and Bug 5017148.

Apart from illustrating dispatcher lock, I'll also describe a problem which I had found a while back. This's involves kernel door implementation too.

I usually begin with looking at what CPUs are doing whenever I take a look at a crash dump from a system hang:

> ::cpuinfo
ID ADDR FLG NRUN BSPL PRI RNRN KRNRN SWITCH THREAD PROC
0 0001041d2b0 1b 1 0 60 no no t-0 3001ba04900 cluster
1 30019fe4030 1d 2 0 101 no no t-0 3003d873a40 rgmd
2 3001a38aab8 1d 1 0 165 yes yes t-0 2a1003ebd20 sched
3 0001041b778 1d 2 0 60 yes yes t-0 3004fac3c80 cluster

CPU 0 is spinning for a mutex 0x30001d7cae0 which is held by thread 0x3004fac3c80 running on CPU 3. Please note that thread will spin for a mutex only when the owner is running and in this case owner of the mutex happens to be onproc on CPU 3.

> 0x30001d7cae0$ 0x30001d7cae0: owner/waiters
3004fac3c80
>

CPU 3 is our clock interrupt CPU (run ::cycinfo -v and figure out where the clock handler is registered) and thread 0x3004fac3c80 on CPU 3 seems to be spinning in cv_block() for sleepq bucket lock (sleepq_head[]). In order to find out which sleepq bucket this thread is looking for, we can look at wait chanel t_wchan (t_lwpchan.lc_wchan) and using the hash function SQHASH(), I found out the right bucket. Since we're already holding thread lock (effectively cpu_thread_lock of CPU 3) and looking for sleepq bucket lock, this would have blocked clock interrupts too. This can be verifyed from the pending clock interrupts in ::cycinfo -v.

Lets disassemble cv_block() thread 3004fac3c80 is stuck

cv_block+0x9c: add %i2, 8, %i0
cv_block+0xa0: call -0x460e0
cv_block+0xa4: mov %i0, %o0

> 0x3004fac3c80::print kthread_t t_lockp
t_lockp = cpu0+0xb8
> cpu0=J
1041b778 // CPU 3
> 0x3004fac3c80::print kthread_t ! grep wchan
lc_wchan = 0x3006fc52d20

And the sleepq bucket happens to be :-

> 0x10471d88::print sleepq_head_t
{
sq_queue = {
sq_first = 0x3001b476ee0
}
sq_lock = 0xff <----- dispatcher lock is held
}

Thread 3003d873a40 running on CPU 1 is spinning in thread_lock_high().

> 3003d873a40::findstack
stack pointer for thread 3003d873a40: 2a1025964a1
[ 000002a1025964a1 panic_idle+0x1c() ]
000002a102596551 prom_rtt()
000002a1025966a1 thread_lock_high+0xc()
000002a102596751 sema_p+0x60()
000002a102596801 kobj_open+0x84()
000002a1025968d1 kobj_open_file+0x44()
[.]
000002a102597011 xdoor_proxy+0x20c()
000002a1025971f1 door_call+0x204()
000002a1025972f1 syscall_trap32+0xa8()
>

Now this's an interesting stack. Looking at the sema_p() code, we see that we first grab the sleepq bucket lock and then try to grab thread lock.

Since the hashing function SQHASH() would return the same index for 0x3006fc52d20 and 0x300819f3118, we see that sema_p() getting stuck on the thread lock which is held by thread running on CPU 3 and thread running on CPU 3 is stuck because sleep queue bucket lock is held by thread running on CPU 1.

> 0x3003d873a40::print kthread_t t_lockp
t_lockp = cpu0+0xb8
> cpu0+0xb8/x
cpu0+0xb8: ff00

Now lets find out the real problem of this deadlock. Lets look t_cpu of thread 0x3003d873a40 and we see that thread 0x3003d873a40 running on CPU 1 has t_lockp pointing to CPU 3's cpu_thread_lock. This's really nasty as we would expect it to point to CPU 1's cpu_thread_lock.

> 0x3003d873a40::print kthread_t ! grep cpu
t_bound_cpu = 0
t_cpu = 0x30019fe4030
t_lockp = cpu0+0xb8 // CPU 3's cpu_thread_lock
t_disp_queue = cpu0+0x78

The cause of this problem is that the door_get_server(), while doing the handoff to server thread, is getting preempted because disp_lock_exit() checks for kernel preemption.

static kthread_t *
door_get_server(door_node_t *dp)
{
 [.]
               /*
                * Mark the thread as ONPROC and take it off the list
                * of available server threads. We are committed to
                * resuming this thread now.
                */
               disp_lock_t *tlp = server_t->t_lockp;
               cpu_t *cp = CPU;

               pool->dp_threads = server_t->t_door->d_servers;
               server_t->t_door->d_servers = NULL;
               /*
                * Setting t_disp_queue prevents erroneous preemptions
                * if this thread is still in execution on another processor
                */
               server_t->t_disp_queue = cp->cpu_disp;
               CL_ACTIVE(server_t);
               /*
                * We are calling thread_onproc() instead of
                * THREAD_ONPROC() because compiler can reorder
                * the two stores of t_state and t_lockp in
                * THREAD_ONPROC().
                */
               thread_onproc(server_t, cp);
               disp_lock_exit(tlp);
               return (server_t);
 [.]

As a result server thread's t_lockp points to incorrect cpu_thread_lock because client thread started running on different CPU when client thread did shuttle_resume() to server thread. We can see that door_return() (which return the results to the caller) releases dispatcher lock without getting preempted, so we didn't notice this problem in door_return().

On the move for cracking another problem now...In fact we don't get sleep if we don't take a look at the crash dump :-)

---

Technorati Tag: OpenSolaris
Technorati Tag: Solaris

Compiler reordering problem

I'm going to write about a compiler reordering problem in door_return() function which was observed in July 2002. The customer was able to reproduce the problem for us and it took me a while to figure out that it was a compiler reordering problem. I must thank our customers for being so co-operative when we get such issues. I must have given instrumented kernels for at least five times before I found out the problem. It's bug 4699850.

The symptom was very clear. System used to panic in Solaris Kernel Dispatcher routines and one of the symptom was system panicing in dispdeq() while removing a kernel thread from the dispatch queue of a CPU.

We know that compiler can reorder C statments if they are independent. Assume this piece of C code:

#define THREAD_SET_STATE(tp, state, lp) \
               ((tp)->t_state = state, (tp)->t_lockp = lp)

t_lockp is a pointer to a dispatcher lock and we don't know whether lp is held or not. When a thread is made TS_ONPROC, the t_lockp of the corresponding thread points to cpu_thread_lock of CPU (cpu_t). In the above mentioned C code, these stores can be reordered can be re-ordered by compiler, so the lp should be held while calling setting the threads state.

In door_return(), when server thread is about to handoff to client thread to return the results, it makes the client thread TS_ONPROC and calls shuttle_resume() on client thread. The responsibility of shuttle_resume() is to make client/server thread TS_ONPROC and the caller sleeps on shuttle_lock sync obj.

While putting a thread onproc, dispatcher routines need not hold cpu_thread_lock and hence in door_return() if we call THREAD_ONPROC(), we effectively lost thread lock on the client thread.

Now lets look at the two stores again. It t_lockp reaches global visibility before t_state, we can effectively lose thread lock on the thread. Assume another thread on different CPU is sending a signal to client door thread. Once the thread lock is lost on the client thread, the thread which is sending signal to client thread could see the old state of client thread (in this case it happens to be TS_SLEEP). Since the state is TS_SLEEP, eat_signal() will do setrun() on the client thread which enqueues client thread in the dispatch queue of the CPU. As a result, we can see some very strange things happening which also included dispdeq() panic.

The following code in door_return() was faulty:

int
door_return(caddr_t data_ptr, size_t data_size,
       door_desc_t *desc_ptr, uint_t desc_num, caddr_t sp)
{
 [.]
                       tlp = caller->t_lockp;
                       /*
                        * Setting t_disp_queue prevents erroneous preemptions
                        * if this thread is still in execution on another
                        * processor
                        */
                       caller->t_disp_queue = cp->cpu_disp;
                       CL_ACTIVE(caller);
                       /*
                        * We are calling thread_onproc() instead of
                        * THREAD_ONPROC() because compiler can reorder
                        * the two stores of t_state and t_lockp in
                        * THREAD_ONPROC().
                        */
                       thread_onproc(caller, cp);
                       disp_lock_exit_high(tlp);
                       shuttle_resume(caller, &door_knob);
 [.]
}

I had used TNF (trace normal form) for finding out this problem. But now we have a powerful tool to trace from userland to kernel and of course it's Dtrace.

---

Technorati Tag: OpenSolaris
Technorati Tag: Solaris
Technorati Tag: DTrace

An interesting signal delivery related problem

Recently, we found an interesting performance problem using Dtrace. The program was when using Virtual timer created using setitimer(2). The interval passed was 10m (one clock tick) but SIGVTALRM signal used to arrive late and sometimes 6 ticks or more. Now how will you Dtrace the code and from where will you start tracing? I'll start tracing from signal generation to delivery. In Solaris kernel to post a signal we use sigtoproc() and eat_signal() is  called on the thread to make the thread on proc (TS_ONPROC) depending upon the state (TS_RUN, TS_SLEEP, TS_STOPPED). psig() is called we kernel finds a pending signal (for instance when returning from trap).

The program spins in userland after setting up the timer. Since the state of thread would be TS_ONPROC, it would be required to poke the  target CPU if thread happens to be running on different CPU. So I started tracing following functions: sigtoproc(), eat_signal(), poke_cpu() and psig(). Now lets take a look at the Dtrace probes output:


CPU Probe ID              Function
 8  11263                 eat_signal:entry  1027637980027920 sig : 28
 8   2981                   poke_cpu:entry  1027637980030560 cpu : 9
 8  11263                 eat_signal:entry  1027637990025440 sig : 28
 8   2981                   poke_cpu:entry  1027637990032160 cpu : 9
 8  11263                 eat_signal:entry  1027638000036320 sig : 28
 8   2981                   poke_cpu:entry  1027638000043600 cpu : 9
 8  11263                 eat_signal:entry  1027638010025520 sig : 28
 8   2981                   poke_cpu:entry  1027638010032240 cpu : 9
 8  11263                 eat_signal:entry  1027638020023840 sig : 28
 8   2981                   poke_cpu:entry  1027638020031280 cpu : 9
 8  11263                 eat_signal:entry  1027638030028720 sig : 28
 8   2981                   poke_cpu:entry  1027638030035920 cpu : 9
 8  11263                 eat_signal:entry  1027638040024480 sig : 28
[.]
 9   8317                       psig:entry  1027638170086480 sig : 28

If you calculate the difference (ie timestamp) between psig() and the first eat_signal(), you will notice that the difference is huge.

1027638170086480-1027637980027920
190058560 = 19 ticks (190 ms)


We also noticed that CPU 8 (from where sigtoproc() is being called by clock_tick()) is poking CPU 9, however CPU 9 is not preempting the current running thread (program which is spinning). So why and how will it happen? In order to understand this, I'll first describe a bit on how preemption works in Solaris. In order to preempt a running thread, kernel sets t_astflag (using aston() macro) and also sets appropriate CPU preemption flag. There are two CPU preemption flags viz: cpu_runrun for user level preemptions and cpu_kprunrun for kernel level preemptions. RT threads can preempt TS or SYS or IA class threads since kernel level preemptions typically kicks off when current  running threads priority is <= 100 (KPQPRI). For signal we don't set CPU level preemption flags. We just need to set t_sig_check and t_astflag followed by poke call.

Since we are interested in user level preemption, we should know what happens when CPU 8 poked CPU 9 (using cross call). If the current running thread on CPU 9 is in userland, then we call user_rtt() which calls trap() if the checks for t_astflag succeeds. So lets check whether t_astflag would be set when we call eat_signal() or not. And that's where the problem was. If the target thread in eat_signal() is TS_ONPROC, we should set t_astflag and then poke the CPU. It will be clear from the following probe that the running thread on CPU 9
was getting preempted because the time quantum finished and clock would have set t_astflag in cpu_surrender().

 9  15055               post_syscall:entry  1027637970269440
 8  11263                 eat_signal:entry  1027637980027920 sig : 28
 8   2981                   poke_cpu:entry  1027637980030560 cpu : 9
[.]
 8  11263                 eat_signal:entry  1027638040024480 sig : 28
 8   2981                   poke_cpu:entry  1027638040026800 cpu : 9
[.]
 8  11263                 eat_signal:entry  1027638110024160 sig : 28
 8   2981                   poke_cpu:entry  1027638110026560 cpu : 9
 8   2435              cpu_surrender:entry  1027638170024720 t:3001b7af3e0
 8   2981                   poke_cpu:entry  1027638170027280 cpu : 9
 8  11263                 eat_signal:entry  1027638170032720 sig : 28
 9   2919              poke_cpu_intr:entry  1027638170033760
 8   2981                   poke_cpu:entry  1027638170034400 cpu : 9
 9   3390                       trap:entry  1027638170037840 type :512, pc: 10984, ast:1
 8   2981                   poke_cpu:entry  1027638170038640 cpu : 9
 9   2919              poke_cpu_intr:entry  1027638170045680
 9   1497               trap_cleanup:entry  1027638170054880 0
 9   8317                       psig:entry  1027638170086480 sig : 28
 9   2278                   trap_rtt:entry  1027638170117440
 9  15055               post_syscall:entry  1027638170143360
 9   8317                       psig:entry  1027638170150880 sig : 2

So Dtrace did help us in finding out where the problem could be. This is just once example. Happy Dtracing...

Dtrace rocks...

Sometime back I had a problem with my desktop and as a result it started crawling whenever Java ticker used to kick in. I think I must share this with the rest of the world. I'd also share a kernel problem that we cracked and it was related to performance. So Dtrace has helped in solving many problems so far.

My desktop running Solaris 10 started crawling when I noticed that Xsun is eating up 68% of CPU. From prstat(1M)

# prstat
  PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP
  594 ******     85M   78M run     30    0  14:03:19  68% Xsun/1
  796 root       16M   13M sleep   59    0   1:06:25 5.8% stfontserverd/18
[.]

I then started Dtrac'ing Xsun and noticed that lwp_sigmask() syscall call is being made too frequently by Xsun. Here is the data :-

# ./syscall.d
^C
Ran for 26 seconds


 writev                                                         2832
 pollsys                                                        3261
 read                                                           5910
 doorfs                                                        27199
 lwp_sigmask                                                  217592

LWP ID     COUNT
1          217592

             libc.so.1`__systemcall6+0x20
             libc.so.1`pthread_sigmask+0x1b4
             libc.so.1`sigprocmask+0x20
             libc.so.1`sighold+0x54
             libST.so.1`fsexchange+0x78
             libST.so.1`FSSessionDisposeFontInstance+0x8c
            9063

             libc.so.1`__systemcall6+0x20
             libc.so.1`pthread_sigmask+0x1b4
             libc.so.1`sigprocmask+0x20
             libc.so.1`sigrelse+0x54
             libST.so.1`fsexchange+0xc0
             libST.so.1`FSSessionGetFontRenderingParams+0x8c

...and many more such stack traces from libST.so.1`fsexchange().

Infact the stack is like this:-

             libc.so.1`__systemcall6+0x20
             libc.so.1`pthread_sigmask+0x1b4
             libc.so.1`sigprocmask+0x20
             libc.so.1`sighold+0x54
             libST.so.1`fsexchange+0x90
             libST.so.1`FSSessionGetFontRenderingParams+0x8c
             libST.so.1`GetRenderProps+0x344
             libST.so.1`GlyphVectorRepQuery+0xf4
             libST.so.1`STGlyphVectorQuery+0xd0
             SUNWXst.so.1`_XSTUseCache+0x68

Notice that in this stack trace, we are calling sighold() and sigrelse() too frequently. So this process is disabling and enabling signals for some reason. Looks like we are rendering characters, but why do we block and unblock signals in this path?. Here is the Dtrace script which was used :-

#!/usr/sbin/dtrace -s

#pragma D option quiet

BEGIN
{
       start = timestamp;

}

syscall:::entry
/execname == "Xsun"/
{
       @s[probefunc] = count();
}

syscall::lwp_sigmask:entry
/execname == "Xsun"/
{
       @c[curthread->t_tid] = count();
       @st[ustack(6)] = count();
}

END
{
       printf("Ran for %d seconds\n\n", (timestamp - start) / 1000000000);

       trunc(@s,5);
       printa(@s);

       printf("\n%-10s %-10s\n", "LWP ID", "COUNT");
       printa("%-10d %@d\n", @c);

       printa(@st);
}

In fact Dtrace could help us in solving much more complex problems. Happy Dtrac'ing...

::cpupart -v for mdb(1m)

Most of you would have used ::cpupart in mdb(1m) to determine the partitions you have on your system. For those who don't know what's partition, then it's an objecct (or kernel entity) which consists of set of CPUs and a global dispatch queue (or global preemption queue). In fact processor sets (which are created from userland using psrset(1M) are abstraction of CPU partitions.

One of the thing which I'm currently working on is to introduce a new option to ::cpupart which will print all the runnable threads in the global dispatch queue of a CPU partition. It's very similar to what ::cpuinfo -v does. Here is the sample output :-

On x86 :-
---------
> ::cpupart -v
ID     ADDR NRUN #CPU CPUS
 0 fec2a1f8  298    2 0-1
               |
               +-->  PRI THREAD   PROC
                     100 d19b1000 sema
                     100 d19aca00 sema
                     100 d19ab200 sema
                     100 d19a7000 sema
                     100 d0b90a00 sema
                     100 d19a5a00 sema
                     100 d19a2e00 sema
                     100 d19aea00 sema
                     100 d19b4200 sema
                     [.]
>

On SPARC :-
-----------
> ::cpupart -v
ID             ADDR NRUN #CPU CPUS
 0          18a8c50   25    8 4-11
                       |
                       +-->  PRI THREAD      PROC
                             100 3000a7b1660 sema
                             100 3000a7c55e0 sema
                             100 3000a7b0d00 sema
                             100 3000a7c4960 sema
                             100 3000a7b5c80 sema
                             100 3000a7b4380 sema
                             100 300084a2c80 sema-1
                             100 3000826c3a0 sema-1
                             [.]
>