Off-CPU Analysis


Measuring low resolution time

Off-CPU analysis is a performance methodology where high resolution off-CPU time is measured and studied. This reveals which code-paths led to time spent waiting (blocked), and can be a quick and generic way to root-cause a wide range of performance issues.

Studying off-CPU time differs from traditional profiling, which often samples the activity of threads at a given interval, and (usually) only examine threads if they are executing work on-CPU. Here, the target are threads that, while processing a workload request, have blocked and are context-switched off-CPU. This method also differs from tracing techniques that instrument various applications functions that commonly block, since this method targets kernel functions that perform the blocking, and so doesn't rely on the foresight to instrument all the right application places.

Threads can leave CPU for a number of reasons, including waiting for file system or network I/O, acquiring a synchronization lock, paging/swapping (virtual memory), an explicit timer and signals. They can also leave CPU for some reasons somewhat unrelated to the current thread's execution, including involuntary context switching due to high demand for CPU resources, and interrupts. Whatever the reason, if this occurs during a workload request (a synchronous code-path), then it is introducing latency.

I'll summarize profiling techniques for off-CPU analysis, and introduce off-CPU as a metric. I'll then use DTrace to measure it, with MySQL as an example target to study. This methodology is suitable for any profiler that can trace kernel events, including perf, SystemTap, and ktap on Linux.

Profiling Techniques

While there are many tools that focus on CPU runtime analysis, the focus here is time spent blocked and off-CPU. I'll summarize sampling and tracing techniques, to show how they compare for identifying this off-CPU time.

CPU Sampling

Many traditional profiling tools sample activity across all CPUs, collecting snapshots of the current instruction address (program counter) or entire stack back trace at a certain rate (eg, 1000 Hertz). This will give counts of either the running function or the stack trace, allowing reasonable estimates to be calculated of where the CPU cycles are being spent. DTrace can sample too (dtrace -n 'profile-1001 /execname == "mysqld"/ { @[ustack()] = count(); }').

Consider application function A() calls function B(), which makes a blocking system call:

    CPU Sampling ----------------------------------------------->
     |  |  |  |  |  |  |                      |  |  |  |  |         
     A  A  A  A  B  B  B                      B  A  A  A  A         
    A(---------.                                .----------)        
               |                                |                   
               B(--------.                   .--)                   
                         |                   |         user-land    
   - - - - - - - - - - syscall - - - - - - - - - - - - - - - - -    
                         |                   |         kernel       
                         X     Off-CPU       |                      
                       block . . . . . interrupt                    

While this can be very effective for studying on-CPU issues, including hot code-paths and adaptive mutex spins, it doesn't gather data when the application has blocked and is waiting off-CPU.

Application Tracing

    App Tracing ------------------------------------------------>
    |          |                                |          |        
    A(         B(                               B)         A)       
                                                                    
    A(---------.                                .----------)        
               |                                |                   
               B(--------.                   .--)                   
                         |                   |         user-land    
   - - - - - - - - - - syscall - - - - - - - - - - - - - - - - -    
                         |                   |         kernel       
                         X     Off-CPU       |                      
                       block . . . . . interrupt                    

Here functions are instrumented so that timestamps are collected when they begin "(" and end ")", so that the time spent in functions can be calculated. If the timestamps include elapsed time and CPU time (eg, using times(2) or getrusage(3C)), then it is also possible to calculate which functions were slow on-CPU vs which functions were slow because they were blocked off-CPU. Unlike sampling, these timestamps can have a very high resolution (nanoseconds).

While this works, a disadvantage is that you either trace all application functions, which can have a significant performance impact (and affect the performance you are trying to measure), or you pick the functions that are likely to block, and hope you didn't miss any. My file system latency tools were examples of this, which traced just the file system I/O functions in MySQL (and I hope I found them all).

Off-CPU Tracing

I'll summarize this here, then explain it in more detail.

    Off-CPU Tracing -------------------------------------------->
                         |                   |                   
                         B                   B                   
                         A                   A                   
    A(---------.                                .----------)        
               |                                |                   
               B(--------.                   .--)                   
                         |                   |         user-land    
   - - - - - - - - - - syscall - - - - - - - - - - - - - - - - -    
                         |                   |         kernel       
                         X     Off-CPU       |                      
                       block . . . . . interrupt                    

With this approach, only the kernel functions that switch the thread off-CPU are traced, along with timestamps and user-land stack back traces. This focuses on the off-CPU events, without needing to trace all of the application functions, or needing to know what the application is. This approach works for any blocking event, for any application: MySQL, Apache, etc.

Off-CPU tracing captures all wait events for any application.

Later on this page I'll trace kernel off-CPU events and include some application level instrumentation to filter out asynchronous wait times (eg, threads waiting for work). Unlike application level instrumentation, I don't need to hunt down every place that may block off-CPU and instrument it; I just need to identify that the application is in a time sensitive code path (eg, during a MySQL query), so that the latency is synchronous to the workload.

Off-CPU

If it is possible to trace the kernel scheduler functions that context switch a thread off-CPU and return it, as well as visibility into user-land context (stack trace), then the approach pictured above is possible. DTrace can not only trace these kernel functions, but also has a stable kernel provider ("sched") for tracing the exact events of interest:

# dtrace -ln 'sched:::*cpu'
   ID   PROVIDER            MODULE                          FUNCTION NAME
18268      sched              unix                             swtch remain-cpu
18289      sched              unix                  resume_from_intr on-cpu
18290      sched              unix                resume_from_zombie on-cpu
18291      sched              unix                            resume on-cpu
18323      sched              unix                  resume_from_intr off-cpu
18324      sched              unix                resume_from_zombie off-cpu
18325      sched              unix                            resume off-cpu

The time spent off-CPU can be calculated as the timestamp delta between the sched:::off-cpu probe and the sched:::on-cpu probe, for the same thread. By itself, that time is not particularly useful, even when summarized as a neat distribution plot:

# dtrace -n 'sched:::off-cpu { self->ts = timestamp; }
    sched:::on-cpu /self->ts/ { @["ns"] = quantize(timestamp - self->ts);
    self->ts = 0; }'
dtrace: description 'sched:::off-cpu ' matched 6 probes
^C

  ns                                                
           value  ------------- Distribution ------------- count    
            4096 |                                         0        
            8192 |@@@                                      55       
           16384 |@@@@@@@@@@@@@                            243      
           32768 |@@@@                                     75       
           65536 |                                         8        
          131072 |@                                        24       
          262144 |                                         3        
          524288 |                                         0        
         1048576 |                                         0        
         2097152 |                                         1        
         4194304 |                                         0        
         8388608 |                                         2        
        16777216 |@@@@@@                                   105      
        33554432 |@@@                                      66       
        67108864 |@@@                                      55       
       134217728 |@@@                                      61       
       268435456 |@                                        28       
       536870912 |@@                                       32       
      1073741824 |                                         0        

That shows two groupings, the first showing threads leaving CPU between 8 and 65 us, and the second showing between 16 ms and 1 second. But that alone is not very useful to know. What we need is context - who the application is (or if it's the kernel), what it's doing, and why it's blocking and leaving CPU.

Context

Adding context is pretty easy: DTrace provides the stack() and ustack() functions, which retrieve the kernel and user-level stacks - the ancestry of the code-path taken. Adding these to the previous one-liner, and also filtering to only match our target application, "mysqld":

# dtrace -x ustackframes=100 -n 'sched:::off-cpu /execname == "mysqld"/ {
    self->ts = timestamp; } sched:::on-cpu /self->ts/ { @[stack(), ustack(), "ns"] =
    quantize(timestamp - self->ts); self->ts = 0; }'
dtrace: description 'sched:::off-cpu ' matched 6 probes
^C
[...]

              genunix`cv_wait+0x61		<- kernel-level stack trace
              zfs`zio_wait+0x5d
              zfs`dmu_buf_hold_array_by_dnode+0x21e
              zfs`dmu_buf_hold_array+0x71
              zfs`dmu_read_uio+0x4d
              zfs`zfs_read+0x19a
              genunix`fop_read+0x6b
              genunix`pread+0x22c
              unix`sys_syscall+0x17a

              libc.so.1`__pread+0xa		<- user-level stack trace
              mysqld`os_file_pread+0x8e
              mysqld`os_file_read+0x3b			<- filesystem I/O
              mysqld`fil_io+0x2b0
              mysqld`buf_read_page_low+0x14e
              mysqld`buf_read_page+0x81
              mysqld`buf_page_get_gen+0x143
              mysqld`btr_cur_search_to_nth_level+0x4dd
              mysqld`row_sel_get_clust_rec_for_mysql+0x9a
              mysqld`row_search_for_mysql+0xdf5
              mysqld`_ZN11ha_innobase13general_fetchEPcjj+0x5b
              mysqld`_Z19join_read_next_sameP14st_read_record+0x32
              mysqld`_Z10sub_selectP4JOINP13st_join_tableb+0x68
              mysqld`_Z9do_selectP4JOINP4ListI4ItemEP8st_tableP9Procedure+0x1fd
              mysqld`_ZN4JOIN4execEv+0x12a9
              mysqld`_Z12mysql_selectP3THDPPP4ItemP10TABLE_LISTjR4ListIS1_ES2_jP8...
              mysqld`_Z13handle_selectP3THDP6st_lexP13select_resultm+0x145
              mysqld`_Z21mysql_execute_commandP3THD+0xe6e
              mysqld`_Z11mysql_parseP3THDPKcjPS2_+0x116
              mysqld`_Z16dispatch_command19enum_server_commandP3THDPcj+0xfc1
              mysqld`_Z10do_commandP3THD+0xb8
              mysqld`handle_one_connection+0x7f7
              libc.so.1`_thrp_setup+0x8d
              libc.so.1`_lwp_start
  ns                                                
           value  ------------- Distribution ------------- count    
          262144 |                                         0        
          524288 |                                         1        
         1048576 |@                                        2        
         2097152 |@@@@@                                    10       
         4194304 |@@@@@@@@@@@@@@@@@@@@@@@@@@               53       
         8388608 |@@@@@@@@                                 16       
        16777216 |                                         1        
        33554432 |                                         0   

The output is many pages long, consisting of hundreds of kernel + user stack traces, plus their time spent waiting off-CPU as distribution plots ("value" == nanoseconds, "count" == number of occurrences in that range). To make the screenful of text a little easier on the eyes, I've added some color (red for kernel, blue for user-land stacks). I've also truncated the output to only show one off-CPU event: file system I/O.

This output is amazing, and is possible by a simplifying principle:

Application stack traces don't change while off-CPU.

This DTrace one-liner is only measuring the stack traces on the sched:::on-cpu event; it doesn't need to gather and save them on the sched:::off-cpu event, or during the time spent off-CPU, since the application stack doesn't change (and the kernel stack may not change much either). It's the application (user-level) stack that usually provides the most helpful context.

Interpreting the stack traces takes a little familiarity with the source code, which depends on how complex the application is and its language. While MySQL is quite complex and has a lot of functionality, the function names are usually intuitive and the code is often fairly straight forward.

The file system I/O latency shown in the distribution, from 1 to 16 ms, matches expectation for random disk I/O latency. It also shows that the file system (while I was tracing) was running at a 0% cache hit rate for this code-path; all I/O were at disk speeds. (This is probably due to this MySQL using application-level caches to cache the frequent requests, leaving a trickle of un-cached and infrequent requests for the file system.)

That stack trace is great - it's showing why the application was blocking and waiting off-CPU, and how long for. This is exactly the sort of information I'm usually looking for. However, this one-liner also catches many stack traces that aren't interesting, including:

[...]
              genunix`cv_wait_sig_swap_core+0x170
              genunix`cv_wait_sig_swap+0x18
              genunix`cv_waituntil_sig+0x13c
              genunix`lwp_park+0x157
              genunix`syslwp_park+0x31
              unix`sys_syscall+0x17a

              libc.so.1`__lwp_park+0x17
              libc.so.1`cond_wait_queue+0x68
              libc.so.1`__cond_wait+0x7b
              libc.so.1`cond_wait+0x23
              libc.so.1`pthread_cond_wait+0x9		<- event waiting
              mysqld`_Z10end_threadP3THDb+0xba
              mysqld`handle_one_connection+0x3e8
              libc.so.1`_thrp_setup+0x8d
              libc.so.1`_lwp_start
  ns                                                
           value  ------------- Distribution ------------- count    
            2048 |                                         0        
            4096 |                                         1        
            8192 |                                         0        
           16384 |                                         0        
           32768 |                                         0        
           65536 |                                         1        
          131072 |                                         3        
          262144 |                                         1        
          524288 |@                                        9        
         1048576 |@@                                       17       
         2097152 |@@@@                                     34       
         4194304 |@@@@@                                    43       
         8388608 |@@@@@@@                                  68       
        16777216 |@@@@@@                                   58       
        33554432 |@@@@@@                                   58       
        67108864 |@@@@                                     41       
       134217728 |@@                                       21       
       268435456 |@                                        12       
       536870912 |@                                        9        
      1073741824 |                                         0  

I believe this stack trace is from a thread ending and waiting in the MySQL thread cache for more work. This isn't so interesting; I'm usually looking to explain why queries are slow, and this latency happens outside a query. I'm not (usually) interested in latencies that occur asynchronously to the queries, such as threads waiting for work.

It would be ideal to only include off-CPU stacks from those wait events that occur synchronously during a query.

Synchronous Context

The DTrace pid provider allows the application to be traced and synchronous workload code-paths to be identified. Using this on MySQL, we can identify if a thread is processing a query, such as by checking that the thread is executing a dispatch_command() function. The following script does this, and includes some usability features to produce rolling status of gathered latency until Ctrl-C is hit; it also includes a minimum latency threshold, set to 10 ms, to only include off-CPU wait events that are longer than this time:

$ cat -n mysqld_pid_offcpu.d
     1	#!/usr/sbin/dtrace -s
     2	/*
     3	 * mysqld_pid_offcpu.d	Trace off-CPU time during queries, showing stacks.
     4	 *
     5	 * USAGE: ./mysqld_pid_offcpu.d -p mysqld_PID
     6	 *
     7	 * TESTED: these pid-provider probes may only work on some mysqld versions.
     8	 *	5.0.51a: ok
     9	 *	5.1.13: ok
    10	 *
    11	 * 27-Feb-2011	Brendan Gregg	Created This.
    12	 */
    13	
    14	#pragma D option quiet
    15	
    16	dtrace:::BEGIN
    17	{
    18		min_ns = 10000000;
    19		printf("Tracing PID %d for queries longer than %d ms\n",
    20		    $target, min_ns / 1000000);
    21		printf("Hit Ctrl-C when ready for off-CPU report.\n\n");
    22	}
    23	
    24	pid$target::*dispatch_command*:entry
    25	{
    26		self->start = timestamp;
    27	}
    28	
    29	sched:::off-cpu
    30	/self->start/
    31	{
    32		self->off = timestamp;
    33	}
    34	
    35	sched:::on-cpu
    36	/self->off && (timestamp - self->off) > min_ns/
    37	{
    38		@offcpu[stack(), ustack()] = quantize(timestamp - self->off);
    39		self->off = 0;
    40	}
    41	
    42	pid$target::*dispatch_command*:return
    43	/self->start && (timestamp - self->start) > min_ns/
    44	{
    45		@time = quantize(timestamp - self->start);
    46	}
    47	
    48	pid$target::*dispatch_command*:return
    49	{
    50		self->start = 0;
    51		self->off = 0;
    52	}
    53	
    54	profile:::tick-1s,
    55	dtrace:::END
    56	{
    57		printf("MySQL query latency (ns):");
    58		printa(@time);
    59		clear(@time);
    60	}
    61	
    62	dtrace:::END
    63	{
    64		printf("Top 10 off-CPU user & kernel stacks, by wait latency (ns):");
    65		trunc(@offcpu, 10);
    66	}

The tick-1s probe prints status every second showing the distribution of query latency beyond 10 ms. The intent is that you watch this rolling status until you catch the latency you are looking for (outliers), and then hit Ctrl-C. The real output is in the @offcpu aggregation, which includes the stack traces and latency distribution (beyond 10 ms) for events during queries.

Here's an example (MySQL 5.0.51a):

# ./mysqld_pid_offcpu.d -p 3475
Tracing PID 3475 for queries longer than 10 ms
Hit Ctrl-C when ready for off-CPU report.

MySQL query latency (ns):

           value  ------------- Distribution ------------- count    
         4194304 |                                         0        
         8388608 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@        257      
        16777216 |@@@@@                                    35       
        33554432 |@                                        10       
        67108864 |@                                        5        
       134217728 |                                         0        
       268435456 |                                         1        
       536870912 |                                         0        

[...waiting to see latency of interest: beyond 1s...]

MySQL query latency (ns):

           value  ------------- Distribution ------------- count    
         4194304 |                                         0        
         8388608 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2        
        16777216 |                                         0        

MySQL query latency (ns):

           value  ------------- Distribution ------------- count    
         4194304 |                                         0        
         8388608 |@@@@@@@@@@@@@                            1        
        16777216 |@@@@@@@@@@@@@                            1        
        33554432 |                                         0        
        67108864 |                                         0        
       134217728 |                                         0        
       268435456 |                                         0        
       536870912 |                                         0        
      1073741824 |@@@@@@@@@@@@@                            1     <- over 1 second
      2147483648 |                                         0     

[got it! Ctrl-C now]
^C
[...]

              genunix`cv_timedwait_sig_hires+0x1db
              genunix`cv_waituntil_sig+0xba
              genunix`poll_common+0x56d
              genunix`pollsys+0xe4
              unix`sys_syscall+0x17a

              libc.so.1`__pollsys+0xa
              libc.so.1`pselect+0x18c
              libc.so.1`select+0x70
              mysqld`os_thread_sleep+0x3f	<- innodb thread concurrency
              mysqld`srv_conc_enter_innodb+0xc4		
              mysqld`_ZN11ha_innobase10index_readEPcPKcj16ha_rkey_function+0x28a
              mysqld`_Z20join_read_always_keyP13st_join_table+0xc7
              mysqld`_Z10sub_selectP4JOINP13st_join_tableb+0xb7
              mysqld`_Z9do_selectP4JOINP4ListI4ItemEP8st_tableP9Procedure+0x1fd
              mysqld`_ZN4JOIN4execEv+0x12a9
              mysqld`_Z12mysql_selectP3THDPPP4ItemP10TABLE_LISTjR4ListIS1_ES2_jP8...
              mysqld`_Z13handle_selectP3THDP6st_lexP13select_resultm+0x145
              mysqld`_Z21mysql_execute_commandP3THD+0xe6e
              mysqld`_Z11mysql_parseP3THDPKcjPS2_+0x116
              mysqld`_Z16dispatch_command19enum_server_commandP3THDPcj+0xfc1
              mysqld`_Z10do_commandP3THD+0xb8
              mysqld`handle_one_connection+0x7f7
              libc.so.1`_thrp_setup+0x8d
              libc.so.1`_lwp_start

           value  ------------- Distribution ------------- count    
         4194304 |                                         0        
         8388608 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 124      
        16777216 |                                         0        


              genunix`cv_wait_sig_swap_core+0x170
              genunix`cv_wait_sig_swap+0x18
              genunix`cv_waituntil_sig+0x13c
              genunix`lwp_park+0x157
              genunix`syslwp_park+0x31
              unix`sys_syscall+0x17a

              libc.so.1`__lwp_park+0x17
              libc.so.1`cond_wait_queue+0x68
              libc.so.1`__cond_wait+0x7b
              libc.so.1`cond_wait+0x23
              libc.so.1`pthread_cond_wait+0x9
              mysqld`os_event_wait+0x27
              mysqld`srv_suspend_mysql_thread+0x29b
              mysqld`row_mysql_handle_errors+0x6e	<- DB lock wait
              mysqld`row_search_for_mysql+0x909
              mysqld`_ZN11ha_innobase10index_readEPcPKcj16ha_rkey_function+0x193
              mysqld`_ZN7handler16read_range_firstEPK12st_key_rangeS2_bb+0x99
              mysqld`_ZN7handler22read_multi_range_firstEPP18st_key_multi_rangeS1...
              mysqld`_ZN18QUICK_RANGE_SELECT8get_nextEv+0x100
              mysqld`_Z8rr_quickP14st_read_record+0x1d
              mysqld`_Z12mysql_updateP3THDP10TABLE_LISTR4ListI4ItemES6_PS4_jP8st_...
              mysqld`_Z21mysql_execute_commandP3THD+0x3581
              mysqld`_Z11mysql_parseP3THDPKcjPS2_+0x116
              mysqld`_Z16dispatch_command19enum_server_commandP3THDPcj+0xfc1
              mysqld`_Z10do_commandP3THD+0xb8
              mysqld`handle_one_connection+0x7f7

           value  ------------- Distribution ------------- count    
         4194304 |                                         0        
         8388608 |@@@@@@@@@@                               1        
        16777216 |@@@@@@@@@@@@@@@@@@@@                     2        
        33554432 |                                         0        
        67108864 |                                         0        
       134217728 |                                         0        
       268435456 |                                         0        
       536870912 |                                         0        
      1073741824 |@@@@@@@@@@                               1        
      2147483648 |                                         0    

I've included the last two off-CPU types and my interpretations: the first is innodb thread concurrency, where threads are put to sleep as part of the algorithm that keeps a certain number of threads running. And by sleep I mean sleep in the programming sense - it's waiting for 10 ms regardless.

The second stack I believe is the DB lock wait code-path, based on DTracing row_mysql_handle_errors() separately.

Since the distribution plot is summarizing latency from 10 ms onwards, this data could be used to provide some early warning that a problem was developing that could slow queries to unacceptable levels (eg, the typical 1 second "slow query").

This is one of the most powerful DTrace scripts I've ever written.

Being able to identify these latencies so quickly is awesome. However, there are a couple of caveats to bear in mind (at least): dispatcher queue latency and involuntary context switching.

Dispatcher Queue Latency

Something that's missing from these stacks is if the latency has included time spent waiting on the CPU dispatcher queue. If the CPUs are running at saturation, then any time a thread steps off-CPU, there may be additional time before it gets its turn stepping back on. That will be included in the reported time. DTrace can trace those dispatcher queue events separately if needed; in practice, CPU saturation is pretty easy to spot, so you are unlikely to be spending much time looking at off-CPU latency when you have a known CPU saturation issue to deal with.

Involuntary Context Switching

If you see a user-level stack trace that doesn't look like it should block, but it has, it could be because the kernel has context switched it off. The kernel-level stack trace may show this, eg:

              unix`preempt+0xd7			<- involuntary context switch
              unix`trap+0x14e8
              unix`sys_rtt_common+0x68
              unix`_sys_rtt_ints_disabled+0x8

              mysqld`_ZN4ItemC2Ev+0xae
              mysqld`_Z21execute_sqlcom_selectP3THDP10TABLE_LIST+0x124
              mysqld`_Z21mysql_execute_commandP3THD+0x2400
              mysqld`_ZN18Prepared_statement7executeEP6Stringb+0x2e9
              mysqld`_ZN18Prepared_statement12execute_loopEP6StringbPhS2_+0x70
              mysqld`_Z19mysqld_stmt_executeP3THDPcj+0xa1
              mysqld`_Z16dispatch_command19enum_server_commandP3THDPcj+0xf85
              mysqld`_Z10do_commandP3THD+0xc2
              mysqld`_Z24do_handle_one_connectionP3THD+0x24e
              mysqld`handle_one_connection+0x37
              mysqld`pfs_spawn_thread+0x50
              libc.so.1`_thrp_setup+0x7e
              libc.so.1`_lwp_start

           value  ------------- Distribution ------------- count    
        67108864 |                                         0        
       134217728 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
       268435456 |                                         0  

Summary

Off-CPU analysis can be an effective way to locate types of latency where threads block and wait for some other event. By tracing this from the kernel scheduler functions that context switch threads, all off-CPU latency types can be analyzed in the same way, without needing to trace multiple sources. To see the context for the off-CPU event to understand why it occurred, both user and kernel stack back traces can be inspected. To only show latencies that affect an application workload, additional instrumentation can be used to identify that context and filter the asynchronous latency events.

On this page these principles were demonstrated using DTrace on MySQL, which observed different types of blocking events and summarized the off-CPU time as distribution plots in nanoseconds. The off-CPU approach can be used for any application which blocks for a variety of reasons, and there isn't already clear visibility into every reason why it may block.

For more on off-CPU analysis, see the visualizations in Off-CPU Flame Graphs and Hot/Cold Flame Graphs.


Last updated: 05-Jan-2014