Luxoft Training предлагает познакомиться с переводом еще одной статьи Рандольфа Гайста «Big Nodes, Concurrent Parallel Execution And High System/Kernel Time».
Рандольф Гайст специализируется на исправлении ошибок, связанных с производительностью баз данных Oracle. Входит в число лучших специалистов в мире в области анализа исполнения SQL-кода и технологий Oracle по оптимизации. Является сертифицированным администратором Oracle базы данных (OCP DBA) версий 8i, 9i и 10g.
Нижеследующее относится только к заказчикам, которые запускают Oracle на крупных серверах с большим количеством ядер в режиме одного экземпляра (данная конкретная проблема не воспроизводится в среде RAC, смотрите ниже объяснение, почему).
К таким заказчикам относится один из моих клиентов, который использует серверы Exadata Xn-8, например, X4-8 со 120 ядрами/240 процессорами на каждый узел (но воспроизводится также и на более старых и меньших моделях с 64 ядрами/128 процессорами на узел).
Недавно базовое приложение решили переписать. Часть этого кода выполняла одни и те же операции для различных наборов данных, во многих случаях – одновременно. Это приводило к тому, что во множестве сеансов использовалось параллельное выполнение запросов. Многие запросы в этом коде не лучшим образом задействовали параллельное выполнение: запросы с очень короткой продолжительностью использовали параллельное выполнение, приводя к нескольким запускам параллельного исполнения в секунду. Такую картину можно увидеть в отчете AWR, показывающем, что в среднем каждую секунду часа запускалось несколько деревьев параллельного выполнения:
Когда новый код был протестирован на данных и нагрузке, полученных с продукционной системы, сначала профиль процессора такого крупного узла (работающего в режиме одного экземпляра) выглядел следующим образом. При этом компьютер не был загружен другими процессами.
Как видно на рис., процессор узла полностью загружен, причем большую часть времени – в режиме ядра/системы. Отчеты AWR показали значительное количество нетипичных событий ожидания PX:
Событие «PX Deq: Slave Session Stats» не должно занимать большое количество времени, поскольку речь идет о передаче статистик сессий ведомых узлов координатору PX в момент их завершения. Очевидно, что-то значительно замедляло это PX-взаимодействие (и заметить это можно было только при чрезмерном использовании параллельного выполнения).
Кроме того, некоторые из более сложных запросов с параллельным выполнением, выполняющие большое количество объединений и приводящие к значительному количеству перераспределений данных, происходили как при замедленной съемке. Хотя почти 100% времени выполнения приходилось на CPU, в Active Session History видно – почти 90% времени относится к операции перераспределения:
SQL statement execution ASH Summary
-----------------------------------------------
| | |
|PX SEND/RECEIVE|PX SEND/RECEIVE|
PERCENTAGE_CPU| PERCENT| CPU PERCENT|
--------------|---------------|---------------|
98| 86| 87|
Запуск того же запроса с тем же планом выполнения и теми же данными на той же машине во время ее простоя показал почти в 20 раз более высокую производительность, а на перераспределение было затрачено менее 40 % времени:
SQL statement execution ASH Summary
-----------------------------------------------
| | |
|PX SEND/RECEIVE|PX SEND/RECEIVE|
PERCENTAGE_CPU| PERCENT| CPU PERCENT|
--------------|---------------|---------------|
96| 38| 37|
Видимо эти запросы вошли в какое-то состязание, происходящее не в Oracle, а снаружи (на уровне операционной системы), и проявляющееся как затраты времени процессора в режиме ядра. Подобное наблюдалось в предыдущих версиях Oracle при «спиннинге» мьютексов.
Снижение чрезмерного использования параллельного выполнения вызвало значительное сокращение времени ЦП. Но по-прежнему большое количество времени работы процессора в режиме ядра/системы было непонятно.
Итак, главный вопрос: на что именно в ядре операционной системы тратилось это время. Ответ на него могли бы помочь найти дополнительные подсказки.
Анализ
Запуск «perf top» на узле во время такого запуска выдал следующий профиль:
PerfTop: 129074 irqs/sec kernel:76.4% exact: 0.0% [1000Hz cycles], (all, 128 CPUs)
-------------------------------------------------------------------------------------------------------------------
samples pcnt function DSO
_______ _____ ________________________ ___________________________________________________________
1889395.00 67.8% __ticket_spin_lock /usr/lib/debug/lib/modules/2.6.39-400.128.17.el5uek/vmlinux
27746.00 1.0% ktime_get /usr/lib/debug/lib/modules/2.6.39-400.128.17.el5uek/vmlinux
24622.00 0.9% weighted_cpuload /usr/lib/debug/lib/modules/2.6.39-400.128.17.el5uek/vmlinux
23169.00 0.8% find_busiest_group /usr/lib/debug/lib/modules/2.6.39-400.128.17.el5uek/vmlinux
17243.00 0.6% pfrfd1_init_locals /data/oracle/XXXXXXX/product/11.2.0.4/bin/oracle
16961.00 0.6% sxorchk /data/oracle/XXXXXXX/product/11.2.0.4/bin/oracle
15434.00 0.6% kafger /data/oracle/XXXXXXX/product/11.2.0.4/bin/oracle
11531.00 0.4% try_atomic_semop /usr/lib/debug/lib/modules/2.6.39-400.128.17.el5uek/vmlinux
11006.00 0.4% __intel_new_memcpy /data/oracle/XXXXXXX/product/11.2.0.4/bin/oracle
10557.00 0.4% kaf_typed_stuff /data/oracle/XXXXXXX/product/11.2.0.4/bin/oracle
10380.00 0.4% idle_cpu /usr/lib/debug/lib/modules/2.6.39-400.128.17.el5uek/vmlinux
9977.00 0.4% kxfqfprFastPackRow /data/oracle/XXXXXXX/product/11.2.0.4/bin/oracle
9070.00 0.3% pfrinstr_INHFA1 /data/oracle/XXXXXXX/product/11.2.0.4/bin/oracle
8905.00 0.3% kcbgtcr /data/oracle/XXXXXXX/product/11.2.0.4/bin/oracle
8757.00 0.3% ktime_get_update_offsets /usr/lib/debug/lib/modules/2.6.39-400.128.17.el5uek/vmlinux
8641.00 0.3% kgxSharedExamine /data/oracle/XXXXXXX/product/11.2.0.4/bin/oracle
7487.00 0.3% update_queue /usr/lib/debug/lib/modules/2.6.39-400.128.17.el5uek/vmlinux
7233.00 0.3% kxhrPack /data/oracle/XXXXXXX/product/11.2.0.4/bin/oracle
6809.00 0.2% rworofprFastUnpackRow /data/oracle/XXXXXXX/product/11.2.0.4/bin/oracle
6581.00 0.2% ksliwat /data/oracle/XXXXXXX/product/11.2.0.4/bin/oracle
6242.00 0.2% kdiss_fetch /data/oracle/XXXXXXX/product/11.2.0.4/bin/oracle
6126.00 0.2% audit_filter_syscall /usr/lib/debug/lib/modules/2.6.39-400.128.17.el5uek/vmlinux
5860.00 0.2% cpumask_next_and /usr/lib/debug/lib/modules/2.6.39-400.128.17.el5uek/vmlinux
5618.00 0.2% kaf4reasrp1km /data/oracle/XXXXXXX/product/11.2.0.4/bin/oracle
5482.00 0.2% kaf4reasrp0km /data/oracle/XXXXXXX/product/11.2.0.4/bin/oracle
5314.00 0.2% kopp2upic /data/oracle/XXXXXXX/product/11.2.0.4/bin/oracle
5129.00 0.2% find_next_bit /usr/lib/debug/lib/modules/2.6.39-400.128.17.el5uek/vmlinux
4991.00 0.2% kdstf01001000000km /data/oracle/XXXXXXX/product/11.2.0.4/bin/oracle
4842.00 0.2% ktrgcm /data/oracle/XXXXXXX/product/11.2.0.4/bin/oracle
4762.00 0.2% evadcd /data/oracle/XXXXXXX/product/11.2.0.4/bin/oracle
4580.00 0.2% kdiss_mf_sc /data/oracle/XXXXXXX/product/11.2.0.4/bin/oracle
Запуск «perf» при сильно загруженных по процессору параллельных ведомых выдал следующий профиль:
0.36% ora_xxxx [kernel.kallsyms] [k]
__ticket_spin_lock
|
--- __ticket_spin_lock
|
|--99.98%-- _raw_spin_lock
| |
| |--100.00%-- ipc_lock
| | ipc_lock_check
| | |
| | |--99.83%-- semctl_main
| | | sys_semctl
| | | system_call
| | | __semctl
| | | |
| | | --100.00%-- skgpwpost
| | | kslpsprns
| | | kskpthr
| | | ksl_post_proc
| | | kxfprienq
| | | kxfpqrenq
| | | |
| | | |--98.41%-- kxfqeqb
| | | | kxfqfprFastPackRow
| | | | kxfqenq
| | | | qertqoRop
| | | | kdstf01001010000100km
| | | | kdsttgr
| | | | qertbFetch
| | | | qergiFetch
| | | | rwsfcd
| | | | qertqoFetch
| | | | qerpxSlaveFetch
| | | | qerpxFetch
| | | | opiexe
| | | | kpoal8
Запуск «strace» по этим параллельным ведомым выдал следующее:
.
.
.
semctl(1347842, 397, SETVAL, 0x1) = 0
semctl(1347842, 388, SETVAL, 0x1) = 0
semctl(1347842, 347, SETVAL, 0x1) = 0
semctl(1347842, 394, SETVAL, 0x1) = 0
semctl(1347842, 393, SETVAL, 0x1) = 0
semctl(1347842, 392, SETVAL, 0x1) = 0
semctl(1347842, 383, SETVAL, 0x1) = 0
semctl(1347842, 406, SETVAL, 0x1) = 0
semctl(1347842, 389, SETVAL, 0x1) = 0
semctl(1347842, 380, SETVAL, 0x1) = 0
semctl(1347842, 395, SETVAL, 0x1) = 0
semctl(1347842, 386, SETVAL, 0x1) = 0
semctl(1347842, 385, SETVAL, 0x1) = 0
semctl(1347842, 384, SETVAL, 0x1) = 0
semctl(1347842, 375, SETVAL, 0x1) = 0
semctl(1347842, 398, SETVAL, 0x1) = 0
semctl(1347842, 381, SETVAL, 0x1) = 0
semctl(1347842, 372, SETVAL, 0x1) = 0
semctl(1347842, 387, SETVAL, 0x1) = 0
semctl(1347842, 378, SETVAL, 0x1) = 0
semctl(1347842, 377, SETVAL, 0x1) = 0
semctl(1347842, 376, SETVAL, 0x1) = 0
semctl(1347842, 367, SETVAL, 0x1) = 0
semctl(1347842, 390, SETVAL, 0x1) = 0
semctl(1347842, 373, SETVAL, 0x1) = 0
semctl(1347842, 332, SETVAL, 0x1) = 0
semctl(1347842, 379, SETVAL, 0x1) = 0
semctl(1347842, 346, SETVAL, 0x1) = 0
semctl(1347842, 369, SETVAL, 0x1) = 0
semctl(1347842, 368, SETVAL, 0x1) = 0
semctl(1347842, 359, SETVAL, 0x1) = 0
.
.
.
Вывод: много времени ЦП тратится на «спиннинг» спин-блокировок (критическая секция кода), вызванный обращениями при параллельном выполнении к «semctl» (семафорам). «strace» показывает, что все обращения к «semctl» используют один и тот же набор семафоров (первый параметр), что и объясняет состязание по этому конкретному набору семафоров (область блокирования – это набор семафоров, а не семафор).
Решение
На основании результатов «perf» инженер Oracle нашел подходящую, но, к сожалению, неопубликованную и закрытую ошибку 2013 г. в версии 12.1.0.2. Для нее есть три различных способа решения проблемы:
1. Запуск с «cluster_database» = true: при этом Oracle будет выполнять запросы по-другому, что приведет к снижению количества вызовов семафоров на два порядка. Мы протестировали этот подход, и он показал немедленную разгрузку по времени работы ядра – вот и объяснение, почему в среде RAC эта конкретная проблема не воспроизводится.
2. Запуск с другими настройками «kernel.sem»: машины Exadata пришли со следующей заранее заданной конфигурацией семафоров:
kernel.sem = 2048 262144 256 256«ipcs» показал следующие массивы семафоров с этой конфигурацией при запуске экземпляра Oracle:
------ Semaphore Arrays --------
key semid owner perms nsems
.
.
.
0xd87a8934 12941057 oracle 640 1502
0xd87a8935 12973826 oracle 640 1502
0xd87a8936 12006595 oracle 640 1502
При уменьшении числа семафоров в наборе и увеличении числа наборов, например, так:
kernel.sem = 100 262144 256 4096
Можно увидеть следующий вывод «ipcs»:
------ Semaphore Arrays --------
key semid owner perms nsems
.
.
.
0xd87a8934 13137665 oracle 640 93
0xd87a8935 13170434 oracle 640 93
0xd87a8936 13203203 oracle 640 93
0xd87a8937 13235972 oracle 640 93
0xd87a8938 13268741 oracle 640 93
0xd87a8939 13301510 oracle 640 93
0xd87a893a 13334279 oracle 640 93
0xd87a893b 13367048 oracle 640 93
0xd87a893c 13399817 oracle 640 93
0xd87a893d 13432586 oracle 640 93
0xd87a893e 13465355 oracle 640 93
0xd87a893f 13498124 oracle 640 93
0xd87a8940 13530893 oracle 640 93
0xd87a8941 13563662 oracle 640 93
0xd87a8942 13596431 oracle 640 93
0xd87a8943 13629200 oracle 640 93
0xd87a8944 13661969 oracle 640 93
0xd87a8945 13694738 oracle 640 93
0xd87a8946 13727507 oracle 640 93
0xd87a8947 13760276 oracle 640 93
0xd87a8948 13793045 oracle 640 93
0xd87a8949 13825814 oracle 640 93
0xd87a894a 13858583 oracle 640 93
0xd87a894b 13891352 oracle 640 93
0xd87a894c 13924121 oracle 640 93
0xd87a894d 13956890 oracle 640 93
0xd87a894e 13989659 oracle 640 93
0xd87a894f 14022428 oracle 640 93
0xd87a8950 14055197 oracle 640 93
0xd87a8951 14087966 oracle 640 93
0xd87a8952 14120735 oracle 640 93
0xd87a8953 14153504 oracle 640 93
0xd87a8954 14186273 oracle 640 93
0xd87a8955 14219042 oracle 640 93
Иными словами, теперь Oracle выделил гораздо больше наборов с меньшим количеством семафоров в наборе. Мы протестировали эту конфигурацию вместо «cluster_database = TRUE» и получили такое же низкое время работы ядра процессора.
3. Есть и третий вариант решения проблемы. Его преимущество: не требуется менять конфигурацию хоста, и конфигурация может быть сделана для каждого экземпляра: существует недокументированный параметр «_sem_per_sem_id», который определяет верхний предел количества семафоров, выделяемых на набор. При установке подходящего значения этого параметра, такого как 100 или 128, конечный результат должен быть таким же. Oracle выделит больше наборов с меньшим количеством семафоров в наборе, но мы не проверяли этот вариант.
Вывод
Некоторые способы использования экземпляра Oracle приводят к состязанию в спин-блокировках на уровне операционной системы Linux ( если Oracle работает в режиме одного экземпляра) и используются рекомендуемые настройки семафоров. Это приводит к тому, что все вызовы семафоров идут в один и тот же набор семафоров. Если заставить Oracle выделить больше наборов семафоров, то вызовы распределяются по большему количеству наборов. Следовательно, состязание значительно снижается.
Существуют, вероятно, указания для внутреннего использования в Oracle о том, что параметры семафоров по умолчанию, рекомендуемые для больших узлов, не являются оптимальными для режима одного экземпляра при определенных обстоятельствах. Но я не знаю, имеется ли исчерпывающее официальное руководство.
Это профиль CPU при точно такой же тестовой нагрузке, как и раньше, с использованием измененных настроек «kernel.sem»:
Также из отчета AWR исчезли связанные с PX события ожидания, которых быть не должно. Производительность значительно улучшилась, также и для сложных запросов, упомянутых выше.
Если вам понравился материал от Рандольфа, то 24 марта он проводит свой мастер-класс в Москве.
Автор: Luxoft
