пятница, 14 апреля 2017 г.

Solaris: диагностика lock contention


Все знают одну из самых известных проблем с производительностью, а, точнее, с масштабированием. Это конкуренция блокировок (lock contention).

На первый взгляд кажется, что многопоточные приложения должны масштабироваться линейно. Так считают зачастую даже весьма опытные администраторы и даже (!) разработчики.

Как бы не так.

Невозможно всегда и везде писать lock-free код. Атомарные операции предельно ограничены областями, в которых их вообще можно использовать.

Стоит, например, заговорить об обработке строк - и привет, строковые операции невозможно выполнять атомарно по определению, они не допускают тривиального копирования, будучи контейнерами.

Наиболее часто в современном коде используются мьютексы, наиболее часто они эксклюзивные. Если говорить о средах разработки Солярис, то штатные библиотеки так густо усыпаны мютексами для гарантирования потокобезопасности, что непонятно, как код вообще может исполняться параллельно (мы же понимаем, что каждая блокировка мьютекса - это точка сериализации, да?). 

Вместе с тем, стоит отметить, что от среды разработки этот эффект, в общем, зависим мало - можно и с использованием GCC/STL понаписать такого, что куча процессорных ядер будет стоять колом в ожидании снятия блокировки.

Впрочем, речь не об этом.

Поговорим о том, как можно диагностировать lock contention, так как возникновение конкуренции блокировок вообще неочевидно и не всегда легко обнаруживается. 

Это важно, так как чтобы устранить bottleneck, надо его сперва обнаружить.

lockstat и standalone diagnostics

Если у вас есть возможность выделить самостоятельную программу для автономного запуска, вы можете использовать утилиту lockstat для диагностики конкуренции блокировок в различных режимах выполнения вашего кода (ну, или не вашего - главное, иметь возможность его запуска).

Я использовал в примерах одну программу, написанную в соавторстве с Joe Lawand, которая выполняется в асинхронном режиме (тредами) в диапазоне от 1 до 65534 треда на процесс.

Программа содержит три глобальных мьютекса (она оптимизирована, мьютексы эксклюзивные - lock_guard, но чрезвычайно короткие и в основных режимах работы используются лишь два из них):

 std::mutex g_cin_mtx, g_cout_mtx, g_log_mtx;     /* cin/cout/log guards */  

Как я и сказал, мьютексы ограничены очень короткой областью видимости:

      {  
           std::lock_guard<std::mutex> lock(g_cout_mtx);  
           std::cout << v_out;  
      }  
   

и снимаются немедленно по завершении критической секции кода.

Для тестов использовался 8-ядерный сервер с двумя процессорами Xeon под Solaris 10:

 root @ khorne / # psrinfo    
 0    on-line  since 04/12/2017 13:18:20  
 1    on-line  since 04/12/2017 13:18:31  
 2    on-line  since 04/12/2017 13:18:31  
 3    on-line  since 04/12/2017 13:18:31  
 4    on-line  since 04/12/2017 13:18:31  
 5    on-line  since 04/12/2017 13:18:31  
 6    on-line  since 04/12/2017 13:18:31  
 7    on-line  since 04/12/2017 13:18:31  
 root @ khorne / # psrinfo -v  
 Status of virtual processor 0 as of: 04/14/2017 19:40:41  
  on-line since 04/12/2017 13:18:20.  
  The i386 processor operates at 2333 MHz,  
     and has an i387 compatible floating point processor.  
 Status of virtual processor 1 as of: 04/14/2017 19:40:41  
  on-line since 04/12/2017 13:18:31.  
  The i386 processor operates at 2333 MHz,  
     and has an i387 compatible floating point processor.  
 Status of virtual processor 2 as of: 04/14/2017 19:40:41  
  on-line since 04/12/2017 13:18:31.  
  The i386 processor operates at 2333 MHz,  
     and has an i387 compatible floating point processor.  
 Status of virtual processor 3 as of: 04/14/2017 19:40:41  
  on-line since 04/12/2017 13:18:31.  
  The i386 processor operates at 2333 MHz,  
     and has an i387 compatible floating point processor.  
 Status of virtual processor 4 as of: 04/14/2017 19:40:41  
  on-line since 04/12/2017 13:18:31.  
  The i386 processor operates at 2333 MHz,  
     and has an i387 compatible floating point processor.  
 Status of virtual processor 5 as of: 04/14/2017 19:40:41  
  on-line since 04/12/2017 13:18:31.  
  The i386 processor operates at 2333 MHz,  
     and has an i387 compatible floating point processor.  
 Status of virtual processor 6 as of: 04/14/2017 19:40:41  
  on-line since 04/12/2017 13:18:31.  
  The i386 processor operates at 2333 MHz,  
     and has an i387 compatible floating point processor.  
 Status of virtual processor 7 as of: 04/14/2017 19:40:41  
  on-line since 04/12/2017 13:18:31.  
  The i386 processor operates at 2333 MHz,  
     and has an i387 compatible floating point processor.  
   

Значение степени параллелизма по умолчанию у программы равно 4 треда на процесс, и в нормальном состоянии конкуренции блокировок не фиксируется:

 root @ khorne / # lockstat -s 10 -I ./store-id-helper      
  
 Profiling interrupt: 16 events in 0.021 seconds (750 events/sec)  
   
 -------------------------------------------------------------------------------  
 Count indv cuml rcnt   nsec CPU+PIL        Caller           
   2 12% 12% 0.00   1280 cpu[0]         i86_mwait+0xd        
   
    nsec ------ Time Distribution ------ count   Stack            
    2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2     cpu_idle_mwait+0x145    
                            idle+0x89          
                            thread_start+0x8      
 -------------------------------------------------------------------------------  
 Count indv cuml rcnt   nsec CPU+PIL        Caller           
   2 12% 25% 0.00   1899 cpu[7]         i86_mwait+0xd        
   
    nsec ------ Time Distribution ------ count   Stack            
    2048 |@@@@@@@@@@@@@@@        1     cpu_idle_mwait+0x145    
    4096 |@@@@@@@@@@@@@@@        1     idle+0x89          
                            thread_start+0x8      
 -------------------------------------------------------------------------------  
 Count indv cuml rcnt   nsec CPU+PIL        Caller           
   2 12% 38% 0.00   1392 cpu[6]         i86_mwait+0xd        
   
    nsec ------ Time Distribution ------ count   Stack            
    2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2     cpu_idle_mwait+0x145    
                            idle+0x89          
                            thread_start+0x8      
 -------------------------------------------------------------------------------  
 Count indv cuml rcnt   nsec CPU+PIL        Caller           
   2 12% 50% 0.00   1467 cpu[5]         i86_mwait+0xd        
   
    nsec ------ Time Distribution ------ count   Stack            
    2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2     cpu_idle_mwait+0x145    
                            idle+0x89          
                            thread_start+0x8      
 -------------------------------------------------------------------------------  
 Count indv cuml rcnt   nsec CPU+PIL        Caller           
   2 12% 62% 0.00   4039 cpu[3]         i86_mwait+0xd        
   
    nsec ------ Time Distribution ------ count   Stack            
    2048 |@@@@@@@@@@@@@@@        1     cpu_idle_mwait+0x145    
    4096 |                0     idle+0x89          
    8192 |@@@@@@@@@@@@@@@        1     thread_start+0x8      
 -------------------------------------------------------------------------------  
 Count indv cuml rcnt   nsec CPU+PIL        Caller           
   2 12% 75% 0.00   1238 cpu[1]         i86_mwait+0xd        
   
    nsec ------ Time Distribution ------ count   Stack            
    2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2     cpu_idle_mwait+0x145    
                            idle+0x89          
                            thread_start+0x8      
 -------------------------------------------------------------------------------  
 Count indv cuml rcnt   nsec CPU+PIL        Caller           
   2 12% 88% 0.00   949 cpu[2]         i86_mwait+0xd        
   
    nsec ------ Time Distribution ------ count   Stack            
    1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2     cpu_idle_mwait+0x145    
                            idle+0x89          
                            thread_start+0x8      
 -------------------------------------------------------------------------------  
 Count indv cuml rcnt   nsec CPU+PIL        Caller           
   1  6% 94% 0.00   1236 cpu[4]         anon_get_slot+0x82     
   
    nsec ------ Time Distribution ------ count   Stack            
    2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1     anon_array_enter+0x105   
                            segvn_faultpage+0x124    
                            segvn_fault+0x98f      
                            as_fault+0x205       
                            pagefault+0x8b       
                            trap+0x3d7         
                            cmntrap+0x140        
 -------------------------------------------------------------------------------  
 Count indv cuml rcnt   nsec CPU+PIL        Caller           
   1  6% 100% 0.00   2581 cpu[4]         mutex_enter+0x10      
   
    nsec ------ Time Distribution ------ count   Stack            
    4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1     hment_prepare+0x6b     
                            hati_pte_map+0x1e3     
                            hati_load_common+0x12b   
                            hat_memload+0x6a      
                            hat_memload_region+0x9   
                            segvn_faultpage+0x264    
                            segvn_fault+0x98f      
                            as_fault+0x205       
                            pagefault+0x8b       
 -------------------------------------------------------------------------------  

Как видно, ожидания снятия блокировок есть, но очень короткие.

Запустим теперь 1000 тредов на один процесс:

 lockstat -s 10 -I ./store-id-helper<t1.txt -1000  

Взгляните, появились ожидания LWP:


Вот именно то, о чем я говорил - конкуренция за блокировки. Потоки стоят в очереди, ожидая освобождения двух мьютексов.

Более наглядно это можно увидеть на гистограмме:


Значения счетчиков события ожидания выросли. Становится видно, что ожидающий процесс переходит в состояние idle и планировщик снимает его с выполнения.

plockstat и runtime diagnostics


Предыдущий пример показывает, как использовать standalone diagnostics. Чаще всего, однако, нам необходима диагностика на живых системах, в режиме runtine execution.

Для этого используем plockstat.

Данная утилита позволяет увидеть lock contention еще более наглядно. Чтобы довести ситуацию до абсурда, выполним два прогона: один в дефолтной конфигурации (4 треда), и один - с запуском максимального возможного количества, по верхней границе лимита программы:

 /* No lock contention - 4 threads */  
   
 root @ khorne / # plockstat -C -n 1000 -s 1 -e 1 -p 4295   
     0  
 root @ khorne / #   
   
   
   
 /* Lock contention - 65534 threads */  
   
   root 17765 16422  2 18:46:14 pts/2    0:05 store-id-helper -65534  
 root @ khorne / # plockstat -C -n 1000 -s 1 -e 1 -p 17765  
     0  
 Mutex block  
   
 -------------------------------------------------------------------------------  
 Count   nsec Lock             Caller  
   22 204393378 libc.so.1`__sbrk_lock    0  
   
    nsec ---- Time Distribution --- count Stack  
    8192 |@@           |   2 0  
    16384 |@            |   1   
    32768 |            |   0   
    65536 |@            |   1   
   131072 |@@           |   2   
   262144 |            |   0   
   524288 |            |   0   
   1048576 |            |   0   
   2097152 |            |   0   
   4194304 |            |   0   
   8388608 |            |   0   
  16777216 |            |   0   
  33554432 |            |   0   
  67108864 |@@@@@@@@@        |   9   
  134217728 |@            |   1   
  268435456 |@@           |   2   
  536870912 |@@           |   2   
 1073741824 |@@           |   2   
 -------------------------------------------------------------------------------  
 Count   nsec Lock             Caller  
   3 447414272 0x449740           0  
   
    nsec ---- Time Distribution --- count Stack  
    65536 |@@@@@@@@        |   1 0  
   131072 |            |   0   
   262144 |            |   0   
   524288 |            |   0   
   1048576 |            |   0   
   2097152 |            |   0   
   4194304 |            |   0   
   8388608 |            |   0   
  16777216 |            |   0   
  33554432 |            |   0   
  67108864 |            |   0   
  134217728 |            |   0   
  268435456 |@@@@@@@@        |   1   
  536870912 |            |   0   
 1073741824 |@@@@@@@@        |   1   
 -------------------------------------------------------------------------------  
 Count   nsec Lock             Caller  
   3 268457301 0x449980           0  
   
    nsec ---- Time Distribution --- count Stack  
    65536 |@@@@@@@@        |   1 0  
   131072 |            |   0   
   262144 |            |   0   
   524288 |            |   0   
   1048576 |            |   0   
   2097152 |            |   0   
   4194304 |            |   0   
   8388608 |            |   0   
  16777216 |            |   0   
  33554432 |            |   0   
  67108864 |            |   0   
  134217728 |            |   0   
  268435456 |@@@@@@@@        |   1   
  536870912 |@@@@@@@@        |   1   
 -------------------------------------------------------------------------------  
 Count   nsec Lock             Caller  
   13 41341873 libc.so.1`_uberdata     0  
   
    nsec ---- Time Distribution --- count Stack  
    8192 |@@@           |   2 0  
    16384 |            |   0   
    32768 |@            |   1   
    65536 |@@@@@@@         |   4   
   131072 |@@@           |   2   
   262144 |            |   0   
   524288 |            |   0   
   1048576 |            |   0   
   2097152 |            |   0   
   4194304 |            |   0   
   8388608 |            |   0   
  16777216 |            |   0   
  33554432 |            |   0   
  67108864 |@@@           |   2   
  134217728 |@            |   1   
  268435456 |@            |   1   
 -------------------------------------------------------------------------------  
 Count   nsec Lock             Caller  
   10 47026176 store-id-helper`g_cout_mtx  0  
   
    nsec ---- Time Distribution --- count Stack  
    8192 |@@           |   1 0  
    16384 |            |   0   
    32768 |@@           |   1   
    65536 |@@           |   1   
   131072 |@@           |   1   
   262144 |@@           |   1   
   524288 |            |   0   
   1048576 |            |   0   
   2097152 |            |   0   
   4194304 |            |   0   
   8388608 |            |   0   
  16777216 |            |   0   
  33554432 |            |   0   
  67108864 |@@@@@@@         |   3   
  134217728 |@@@@          |   2   
 -------------------------------------------------------------------------------  
 Count   nsec Lock             Caller  
   1 268435456 0x4497c0           0  
   
    nsec ---- Time Distribution --- count Stack  
  268435456 |@@@@@@@@@@@@@@@@@@@@@@@@|   1 0  
 -------------------------------------------------------------------------------  
 Count   nsec Lock             Caller  
   1 268435456 0x449700           0  
   
    nsec ---- Time Distribution --- count Stack  
  268435456 |@@@@@@@@@@@@@@@@@@@@@@@@|   1 0  
 -------------------------------------------------------------------------------  
 Count   nsec Lock             Caller  
   1 134217728 0x449880           0  
   
    nsec ---- Time Distribution --- count Stack  
  134217728 |@@@@@@@@@@@@@@@@@@@@@@@@|   1 0  
 -------------------------------------------------------------------------------  
 Count   nsec Lock             Caller  
   1  262144 0x449840           0  
   
    nsec ---- Time Distribution --- count Stack  
   262144 |@@@@@@@@@@@@@@@@@@@@@@@@|   1 0  
 -------------------------------------------------------------------------------  
 Count   nsec Lock             Caller  
   1  262144 0x449800           0  
   
    nsec ---- Time Distribution --- count Stack  
   262144 |@@@@@@@@@@@@@@@@@@@@@@@@|   1 0  
 root @ khorne / #   
   

Тут все совершенно очевидно. Нет конкуренции - нет вывода, выводится ноль и все. Во втором случае у нас в ожидании находится свыше 60к процессов, мы видим, что ожидания вызывает именно мьютекс  g_cout_mtx.

Как видите, все просто. Если, при этом, вы видите исходный код, то определение проблемных мест сразу позволяет перейти к их оптимизации.

PS. Интересный факт. Древний (и давно устаревший) top показывает максимум 999 LWP:


Впрочем, в Солярис он отсутствует (его устанавливают отдельно - а потом ему всецело верят, что зря).

А вот штатный prstat показывает все честно, как есть (и в нем нет странных лимитов):