DTrace to the rescue!

We recently migrated data to some older servers and ran into a performance problem during peakhours.

Analysis

On our busiest days, we've seen the load go up to over 300. Luckily this is a SPARC system, and it was still somewhat responsive. Not bad for an old 2 Socket system...

Looking at the CPU utilization using vmstat, showed a high percentage of time spent in SYS.


You can see this in the two performance graphs (the graphs were made on a Sunday, with a lower load).


















After looking at the processes with prstat -Lm (microstate accounting) and seeing the high SYS-percentage, we decided to look at what the kernel is doing.

Solaris has a nifty tool called lockstat. This is what it revealed:

# lockstat -i 133 -I sleep 5

Profiling interrupt: 1394 events in 5.241 seconds (266 events/sec)

Count indv cuml rcnt     nsec CPU+PIL                Caller                 
-------------------------------------------------------------------------------
  214  15%  15% 0.00     1982 cpu0                   (usermode)             
  174  12%  28% 0.00     3809 cpu[0]                 (usermode)             
  105   8%  35% 0.00     6559 cpu[0]                 dnlc_purge_vp+0xa4     
   53   4%  39% 0.00     3583 cpu0                   dnlc_purge_vp+0xa4     
   35   3%  42% 0.00     2684 cpu0                   copyout_more+0x190     
   31   2%  44% 0.00     7042 cpu[0]                 dnlc_purge_vp+0xa8     
   24   2%  46% 0.00     6714 cpu[0]                 dnlc_purge_vp+0x148    
   19   1%  47% 0.00     3929 cpu0                   dnlc_purge_vp+0xa8     
   15   1%  48% 0.00     5041 cpu[0]                 mutex_enter+0x8        
   13   1%  49% 0.00     3799 cpu0                   mutex_enter+0x8        
   12   1%  50% 0.00     3449 cpu0                   dnlc_purge_vp+0x148    
   10   1%  51% 0.00     2712 cpu[0]                 i_ddi_splx+0x1c        
    9   1%  51% 0.00     2320 cpu0                   hwblkclr+0x94          
    8   1%  52% 0.00     7265 cpu[0]                 dnlc_purge_vp+0xa0     
    8   1%  52% 0.00     3183 cpu0                   hwblkclr+0x9c          
    8   1%  53% 0.00     3397 cpu0                   hwblkclr+0x98          
    7   1%  53% 0.00     2592 cpu0                   copyout_more+0x194     
    5   0%  54% 0.00     2005 cpu0                   segmap_getmapflt+0x124 
    4   0%  54% 0.00     3784 cpu[0]+11              disp_getwork+0x88      
    4   0%  54% 0.00     1441 cpu[0]+11              spl6+0x14              
    4   0%  55% 0.00     3253 cpu[0]                 spl6                   
    4   0%  55% 0.00     5103 cpu[0]                 _resume_from_idle+0x1f8
    4   0%  55% 0.00     2466 cpu0+0x6               pci_pbm_dma_sync+0x8c  
    4   0%  56% 0.00     2735 cpu0                   hwblkclr+0xb0          
    4   0%  56% 0.00     2555 cpu0                   dnlc_purge_vp+0xa0     
    4   0%  56% 0.00     2998 cpu0                   page_lookup_create+0x90
    3   0%  56% 0.00     2449 cpu[0]+11              disp_getwork+0x15c     
    3   0%  57% 0.00     3502 cpu[0]+11              disp_getwork+0xa4      
    3   0%  57% 0.00     3233 cpu[0]+11              i_ddi_splx             
    3   0%  57% 0.00     6187 cpu[0]                 r4find+0x14c           
    3   0%  57% 0.00     5585 cpu[0]                 copyout+0x25c   

There's a strange function stealing almost 20% of the interrupts:  dnlc_purge_vp

The dnlc_purge_vp function belongs to the directory name lookup cache. It purges cache entries from time to time. You can read more about it here.

Next step was to find out how much time is spend in this function. A small dtrace script helped us:

purge.d: 
fbt::dnlc_purge_vp:entry
{
        self->t = timestamp;
}

fbt::dnlc_purge_vp:return
/self->t/
{
        @["latency"] = quantize((timestamp-self->t)/1000);
        self->t = 0;
}

Running it, gives us a nice latency distribution table:

#  dtrace -s purge.d                   
dtrace: script 'purge.d' matched 2 probes
^C

  latency                                          
           value  ------------- Distribution ------------- count   
             128 |                                         0       
             256 |                                         1       
             512 |                                         0       
            1024 |                                         2       
            2048 |@                                        6       
            4096 |@                                        10      
            8192 |@@@@@@                                   65      
           16384 |@@@@@@@@@@@@@@@@@@@@@@                   247     
           32768 |@@@@@@@@@@                               112     
           65536 |                                         3       
          131072 |                                         5       
          262144 |                                         3
          524288 |                                         0       

Looking at the result, we can see that most function calls take about 8-32ms. Really slow!

Solution

Knowing that the CPU is too slow for purging a large cache, we decided to decrease the cache from its default size to 25% of the default size. The ncsize kernel parameter is unfortunately not dynamic. We had to enter it in /etc/system and reboot the OS.

This was done on an indentical system with approx. the same load, and this is what lockstat reported after the reboot:

# lockstat -i 133 -I sleep 5  

Profiling interrupt: 1344 events in 5.054 seconds (266 events/sec)

Count indv cuml rcnt     nsec CPU+PIL                Caller                 
-------------------------------------------------------------------------------
   55   4%   4% 0.00     2301 cpu0                   (usermode)             
   47   3%   8% 0.00     2510 cpu[0]                 (usermode)             
   42   3%  11% 0.00     1717 cpu[0]                 splx+0x1c              
   41   3%  14% 0.00     1667 cpu0                   splx+0x1c              
   29   2%  16% 0.00     1718 cpu0                   idle+0x12c             
   26   2%  18% 0.00     1758 cpu[0]+11              disp_getwork+0x98      
   22   2%  19% 0.00     1511 cpu[0]                 disp_getwork+0x174     
   20   1%  21% 0.00     1249 cpu[0]+11              disp_getwork+0x78      
   20   1%  22% 0.00     1406 cpu0+0xb               disp_getwork+0x98      
   20   1%  24% 0.00     1627 cpu0+0xb               disp_getwork+0x88      
   20   1%  25% 0.00     1498 cpu0+0xb               i_ddi_splhigh+0x14     
   18   1%  27% 0.00     1324 cpu[0]+11              splx                   
   18   1%  28% 0.00     1663 cpu0                   disp_getwork+0x174     
   17   1%  29% 0.00     1592 cpu0+0xb               disp_getwork+0x78      
   16   1%  31% 0.00     1284 cpu[0]+11              i_ddi_splhigh+0x14     
   16   1%  32% 0.00     1500 cpu[0]                 disp_getwork+0x1b4     
   16   1%  33% 0.00     1602 cpu[0]                 idle+0x12c             
   16   1%  34% 0.00     1438 cpu[0]                 i_ddi_splhigh+0xc      
   16   1%  35% 0.00     1696 cpu0+0xb               splx                   
   14   1%  36% 0.00     1571 cpu0                   idle+0xf4              
   14   1%  37% 0.00     1411 cpu0                   i_ddi_splhigh          
   13   1%  38% 0.00     1664 cpu[0]                 i_ddi_splhigh          
   12   1%  39% 0.00     1697 cpu[0]                 idle+0xec          
...

There's no dnlc_purge_vp function in the first 40% of the interrupts!

Running the dtrace script also confirms, that purge times have dropped linearly to about 25%:

# dtrace -s purge.d
dtrace: script 'purge.d' matched 2 probes
^C

  latency                                          
           value  ------------- Distribution ------------- count   
             256 |                                         0       
             512 |@                                        1       
            1024 |@                                        2       
            2048 |@@@@@@                                   10      
            4096 |@@@@@@@@@@@@@@@@@@@@                     32      
            8192 |@@@@@@@@@@@@                             19      
           16384 |                                         0       

Looking at the system over a day, the load and CPU utilization was much lower:










Conclusion

Solaris' dtrace tool is not just a marketing gag, but is real value for all production enviroments. We were able to find the bottleneck in no time (about 30 minutes of investigation + in this case reboot during off-peak hours).

Most importantly, we didn't have to risk production as dtrace is production safe.

Comments

Chris said…
Cooler Beitrag
September 1, 2010 at 4:04 PM
Post a Comment

Popular posts from this blog

Heating up the Data Pipeline (Part 1)

Image
Pre-Processing Data I often hear the question from our customers, how data can be transformed prior to indexing in Splunk. Damien from  Baboonbones  has done a tremendous job in creating add-ons   providing custom inputs for Splunk. Most of his custom inputs provide the means to pre-process data by allowing custom event handlers to be written. Sometimes you still want to pre-process data that gets collected from Splunk's standard input types, like file monitors, Windows EventLogs, scripted inputs etc. Also, not everyone is capable of writing custom event handlers. A requirement these customers have, is that they have rolled out a large number of Splunk Universal Forwarders and they do not want to install another agent. To summarize, the solution capable of pre-processing data, should be easy to use, be easily integrated and be build on top of their existing architecture. How to plumb Splunk Pipelines Splunk has its own fittings to connect a Universal Forwar
Read more

Heating up the Data Pipeline (Part 3)

Image
Welcome back to the "Heating up the Data Pipeline" blog series. In part 1 we talked about how to route data from Splunk to a 3rd party system. In part 2 walked through a simple data flow that passes data collected from Splunk Forwarders through Apache NiFi back to Splunk over the HTTP Event Collector. In this part, we will look at a more complex use case, where we route events to an index, based on the sending host's classification. The classification will be looked up from a CSV file. We will make use of Apache NiFi's new Record-Oriented  data handling capabilities, which will look initially a bit more complicated, but once you grasp it, it will make further Use Cases easier and faster to build. High-Level Dataflow We will again start with our ListentTCP input, but this time we will send the data to another Processor Group. The Processor Group will again emit events suitable for Splunk HEC. Note that we have increased the Max Batch Size from 1
Read more

SLOG Latency

Image
After reading Brendan's newest blog entry, I was curious about what kind of slog latency we can see for our data migration load. To remind you, only synchronous writes go into the slog SSD devices. As this is a migration running, we can see mostly NFS write operations: In our configuration the SSD slog is mirrored (HDD4 and HDD8). Hence the same number of IOPS: The next picture shows us the latency for our SDD SLOG Device HDD 4. We can see here that latencies start at 79 us and are mostly under 200 us. There are some outliers, but approx. 95% are under 500 us: This matches quite well with the values Brendan blogged about (137-181 us), which includes NFSv3 latency. For reference (no picture here), we can see latencies of about 170-500 us mostly for NFSv4. By the way. SLOG Devices are mostly one way devices, as shown here. Only if things go really bad, they are read from...
Read more