Oracle. The impact of a commit on task execution time.

Many probably know that frequent commits are bad and slow, but how bad and how slow is not clear, and this small test is designed to demonstrate the impact of this event.

I’ll note right away that commits should be made exactly when the business process requires it, or when there is any other significant reason, rather than just ‘in case.’

Test environment:

Oracle 19.23

OS: OEL 8.5 4.18.0-513.24.1.el8_9.x86_64

RAM: 128GB

CPU: AMD Threadripper 1920x

Disks:

Disk group for data files: +ORADATA: SATA SSD GeIL R3 512GB

Disk group for redo logs: +ADATAD1: XPG GAMMIX S11 Pro PCI E 3.0 x4

Disk group for archive logs: +ARCHLOG: SATA SSD GeIL R3 512GB

+ORADATA and +ARCHLOG are located on the same physical disk SATA SSD GeIL R3 512GB.

The code that will act as the load (intensive business process activity):

Variant 1:

declare
v_loop number;
v_seq number;
v_text varchar2(3000);
v_rtext varchar2(3000);
begin
  execute immediate 'truncate table t1';
  dbms_output.put_line('Start: '||to_char(sysdate,'dd.mm.yyyy hh24:mi:ss'));
  dbms_workload_repository.create_snapshot;
  v_loop:=1;
  select dbms_random.string(opt => 'X',len => 3000) into v_rtext from dual;
  while v_loop<5000001
    loop
      v_seq:=t1_seq.nextval;
      insert into t1(id,text) values(v_seq,v_rtext);
      commit write wait;
      select t1.text into v_text from t1 where id=v_seq;
      update t1 set t1.text='update' where id=v_seq;
      commit write wait;
      delete from t1 where id=v_seq;
      commit write wait;
      v_loop:=v_loop+1;
      end loop;
      dbms_workload_repository.create_snapshot;
      dbms_output.put_line('End: '||to_char(sysdate,'dd.mm.yyyy hh24:mi:ss'));
   end;

Variant 2:

declare
v_loop number;
v_seq number;
v_text varchar2(3000);
v_rtext varchar2(3000);
begin
  execute immediate 'truncate table t1';
  dbms_output.put_line('Start: '||to_char(sysdate,'dd.mm.yyyy hh24:mi:ss'));
  dbms_workload_repository.create_snapshot;
  v_loop:=1;
  select dbms_random.string(opt => 'X',len => 3000) into v_rtext from dual;
  while v_loop<5000001
    loop
      v_seq:=t1_seq.nextval;
      insert into t1(id,text) values(v_seq,v_rtext);
      select t1.text into v_text from t1 where id=v_seq;
      update t1 set t1.text='update' where id=v_seq;
      delete from t1 where id=v_seq;
      commit write wait;
      v_loop:=v_loop+1;
      end loop;
      dbms_workload_repository.create_snapshot;
      dbms_output.put_line('End: '||to_char(sysdate,'dd.mm.yyyy hh24:mi:ss'));
   end;

The difference between the first and second options is that the first option has 3 commits within the loop, while the second has 1 commit within the loop. Also, the ‘commit write wait’ construct is chosen to avoid PL/SQL optimization, as this commit variant is used if the code is not written in PL/SQL.

Variant 1 took 23 minutes and 6 seconds (1386 seconds) to complete.

Variant 2 took 12 minutes and 51 seconds (771 seconds) to complete.

Variant 3 (commit executed only at the end of the loop) took 503 seconds, but it’s not considered for evaluation.

So, Variant 2 is nearly twice as fast.

Reasons why Variant 1 took longer:

Further calculations are done with a certain margin of error, and it is assumed that all statistics relate only to the tasks being performed.

Variant 1 took 501 seconds for log file sync (lfs) out of 1386 seconds, while variant 2 took 192 seconds for log file sync (lfs) out of 771 seconds. By subtracting 501 from 1386, we get 885 seconds. Mathematically excluding all intermediate commits in the loop from variant 1, it still takes more time than variant 2, with 885 seconds versus 771 seconds.

Graph of the number of SQL statement executions per second for ‘Variant 1,’ ‘Variant 2,’ and ‘Variant 3’:

As seen on the graphs, there are some ‘dips,’ the explanations for which I will try to provide in the following note.

AWR reports for ‘Variant 1,’ ‘Variant 2,’ ‘Variant 3,’ and AWR comparison between ‘Variant 1’ vs ‘Variant 2’.

Oracle. Влияние коммита на время выполнения задачи.

Многие наверно знают, что частые коммиты — это плохо и медленно, но насколько плохо и насколько медленно, не понятно и данный маленький тест призван показать влияние этого события.

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

Тестовый стенд:

Oracle 19.23

OS: OEL 8.5 4.18.0-513.24.1.el8_9.x86_64

RAM: 128GB

CPU: AMD Threadripper 1920x

Диски:

Дисковая группа для датафайлов: +ORADATA: SATA SSD GeIL R3 512GB

Дисковая группа для редологов:    +ADATAD1: XPG GAMMIX S11 Pro PCI E 3.0 х4

Дисковая группа для архивных логов: +ARCHLOG: SATA SSD GeIL R3 512GB

+ORADATA и +ARCHLOG расположены на одном физическом диске SATA SSD GeIL R3 512GB.

Код, который будет выступать в виде нагрузки (бурной деятельности бизнес-процессов):

Вариант номер 1:

declare
v_loop number;
v_seq number;
v_text varchar2(3000);
v_rtext varchar2(3000);
begin
  execute immediate 'truncate table t1';
  dbms_output.put_line('Start: '||to_char(sysdate,'dd.mm.yyyy hh24:mi:ss'));
  dbms_workload_repository.create_snapshot;
  v_loop:=1;
  select dbms_random.string(opt => 'X',len => 3000) into v_rtext from dual;
  while v_loop<5000001
    loop
      v_seq:=t1_seq.nextval;
      insert into t1(id,text) values(v_seq,v_rtext);
      commit write wait;
      select t1.text into v_text from t1 where id=v_seq;
      update t1 set t1.text='update' where id=v_seq;
      commit write wait;
      delete from t1 where id=v_seq;
      commit write wait;
      v_loop:=v_loop+1;
      end loop;
      dbms_workload_repository.create_snapshot;
      dbms_output.put_line('End: '||to_char(sysdate,'dd.mm.yyyy hh24:mi:ss'));
   end;

Вариант номер 2:

declare
v_loop number;
v_seq number;
v_text varchar2(3000);
v_rtext varchar2(3000);
begin
  execute immediate 'truncate table t1';
  dbms_output.put_line('Start: '||to_char(sysdate,'dd.mm.yyyy hh24:mi:ss'));
  dbms_workload_repository.create_snapshot;
  v_loop:=1;
  select dbms_random.string(opt => 'X',len => 3000) into v_rtext from dual;
  while v_loop<5000001
    loop
      v_seq:=t1_seq.nextval;
      insert into t1(id,text) values(v_seq,v_rtext);
      select t1.text into v_text from t1 where id=v_seq;
      update t1 set t1.text='update' where id=v_seq;
      delete from t1 where id=v_seq;
      commit write wait;
      v_loop:=v_loop+1;
      end loop;
      dbms_workload_repository.create_snapshot;
      dbms_output.put_line('End: '||to_char(sysdate,'dd.mm.yyyy hh24:mi:ss'));
   end;

Отличие первого и второго варианта в том, что первый вариант имеет 3 коммита в цикле, а второй 1 коммит в цикле. Также, конструкция commit write wait выбрана для того, чтобы избежать оптимизации PL/SQL, т.к. данный вариант коммита применяется если код написан не на PL/SQL.

Вариант 1, выполнился за 23 минуты и 6 секунд(1386 секунд)

Вариант 2, выполнился за 12 минут и 51 секунду(771 секунд).

В не зачёта: Вариант 3(коммит выполняется только по окончанию цикла), выполнился за 503 секунды.

Т.е. вариант 2 быстрее почти в 2 раза.

На что вариант 1 потратил время(почему он медленнее):

Далее расчеты делаются с определённой погрешностью и предполагается, что все статистики относятся только к выполняемым задачам.

Вариант 1 из 1386 секунд, потратил на log file sync(lfs) 501 сек, а вариант 2 из 771 секунд, потратил на log file sync(lfs) 192 сек. Отняв от 1386, 501, получим 885 сек, т.е. математически исключим все промежуточные коммиты в цикле из варианта 1, всё равно вариант 1  затрачивает времени больше, чем вариант 2, 885сек против 771сек.

График количества выполнений SQL выражений в секунду для “вариант 1”,“вариант 2” и “вариант 3”:

    

Как видно на графиках, есть некие “провалы”, объяснения которым я попробую дать в следующей заметке.

AWR отчеты для “вариант 1”, “вариант 2”, “вариант 3” и AWR сравнение “вариант 1” vs “вариант 2”:

Log file sync switching to post/wait. eng.

DB version: Oracle 19.9 x86.

In this note, I will visually demonstrate how the transition of lgwr from poll->post to post/wait mode can look like.

Investigate time when it happened by using trace file of lgwr process:

*** 2023-02-16T12:45:09.010167+06:00 
Log file sync switching to post/wait 
Current approximate redo synch write rate is 10286 per sec
Fig.1
Fig.2

Figure 1 shows that the transition of lgwr from poll->post to post/wait mode led to a doubling of the log file sync wait time, from 250 microseconds to 500 microseconds.
Additionally, the number of redo blocks written in 128KB doubled. Although not visible in the graphs, there is also a decrease in the number of redo blocks written that are much smaller than 128KB (4, 8, 16, 32KB, etc).

Figure 2 shows how the number of log file parallel write waits (oracledb_event_p3_log_file_parallel_write_p2) has changed.
The number of waits has decreased by half, but the duration of a single log file parallel write wait (oracledb_event_p2_log_file_parallel_write_p2) has increased by an average of 50%, from 50 microseconds to 75 microseconds.

It looks like some sort of ferry mode where fewer operations are performed with larger block sizes, resulting in a 2x reduction in response time. This behavior is subject to change according to the algorithm and database parameters associated with the adaptive operation of LGWR.

You can read more here:

  1. Adaptive Switching Between Log Write Methods can Cause ‘log file sync’ Waits (Doc ID 1462942.1)
  2. ADAPTIVE LOG FILE SYNC: ORACLE, PLEASE DON’T DO THAT AGAIN

Actually, the solution is: ALTER SYSTEM SET «_use_adaptive_log_file_sync» = FALSE;

Log file sync switching to post/wait

Версия: Oracle 19.9

В данной заметке показано наглядно, как может выглядеть переход lgwr от poll->post к режиму post/wait.

Смотрим в трейс файл процесса lgwr, находим там:

*** 2023-02-16T12:45:09.010167+06:00

Log file sync switching to post/wait

Current approximate redo synch write rate is 10286 per sec

Идём в графану и смотрим визуализацию этого события:

Рис1.

Рис2.

На рисунке 1 показано, что переход lgwr от poll->post к режиму post/wait привёл к увеличению ожидания log file sync в 2 раза, с 250мксек до 500мксек, также, увеличилось количество записи редо блоком в 128KB в два раза. На графики этого не видно, но также имеется снижение количества записи редо блоком гораздо меньшим чем 128KB(4,8,16,32KB etc).

На рисунке 2 показано, как изменилось количество ожиданий log file parallel write(oracledb_event_p3_log_file_parallel_write_p2). Количество ожиданий уменьшилось в два раза, в тоже время длительность одного ожидания log file parallel write(oracledb_event_p2_log_file_parallel_write_p2) увеличилось, в среднем на 50%, с 50мксек до 75мксек.

Выглядит как какой-то челночный режим, выполнить меньше операций большим размером блока, что даёт снижение отклика в 2 раза. Данное поведение меняется согласно алгоритму и параметрам базы данных связанных с адаптивной работы LGWR.

Подробнее можно почитать тут:

  1. Adaptive Switching Between Log Write Methods can Cause ‘log file sync’ Waits (Doc ID 1462942.1)
  2. ADAPTIVE LOG FILE SYNC: ORACLE, PLEASE DON’T DO THAT AGAIN

Собственно, решение такое: ALTER SYSTEM SET «_use_adaptive_log_file_sync» = FALSE;

Резкий рост log file sync и buffer busy wait при незначительном повышении нагрузки.

Для начала приведу первоисточник, благодаря которому, проблема была локализована и устранена:

  1. High log file sync waits? Check log parallelism!

2.  Finding the root cause of “CPU waits” using stack profiling

В первоисточнике вы можете подробнее ознакомится с механизмами и параметрами, которые будут упомянутs здесь, я же только опишу конечный результат, который получился у меня.

Описание проблемы: после того как бд переехала на сервер с 4мя сокетами, по достижению определённой нагрузки, резко вырастали ожидания  log file sync и buffer busy wait.

Окружение: RHEL 7, Oracle 12.1.0.2 + BP, ASM 12.1.0.2 + BP

Как это выглядит:

AWR:

Lab128:

Промежутки времени для AWR и Lab128 взяты немного разные, поэтому есть разница в цифрах, но общей картины это не меняет, всё очень плохо.

1.      Первым делом решено было бороться с log file sync(LFS).

Из ссылки 1 я узнаю про параметр _log_parallelism_max.

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

1.      Ожидание log file sync гораздо выше(более чем в 2 раза) log file parallel write

Например, log file sync= 1мс, а log file parallel write=2мс и выше.

2.      Оценить значении log file parallel write P3(Number of I/O requests) из v$active_session_history/dba_active_session_history в нагруженный и не нагруженный период. P3 должен изменяться, от 1 до _log_parallelism_max т.е. быть 2,3,4,5…

3.      При повышении значения log file parallel write P3(Number of I/O requests), log file sync должен расти, но возможно не обязан.

4.      Количество потоков CPU больше, либо равно 64.

5.      Log File Parallel Writes Take Longer with a Higher CPU Count (Doc ID 1980199.1)

Я применил значение _log_parallelism_max=2

Результат:

AWR:

log file sync снизился с 5.68мс до 1.15мс(по AWR), казалось бы победа, но нет, присутствует ожидание buffer busy wait, которое оказывает сильное влияние на работу приложения, да и само значение log file sync всё ещё выше, чем на старом сервере, даже после улучшения.

2.   Здесь переходим ко второй части.

Ожидания buffer busy wait с работой приложения никак не связано, профиль нагрузки практически не менялся. Kоличественные характеристики полезной работы бд: dml выполненных в секунду, количество коммитов в секунду, LIO в секунду в целом выросли на 5%-10% и после переезда на 4 сокета, buffer busy wait раскрылся во всей красе, опять таки только по достижению определённой нагрузки(превышение на 5%-10%), если её не превышать, то всё хорошо.

Всё хорошо — это означает, что ожидания buffer busy wait стремятся к нулю, а log file sync значительно меньше 1мс (0.3-0.6мс) для работы под нужной нагрузкой.

Вышеописанное должно привести на мысль, что что-то не так с железом, либо проблема на уровне OS. Здесь на помощь приходит вторая ссылка, из которой становится понятно, что вероятно дело в kernel.numa_balancing. И действительно, если поискать на MOS используя kernel.numa_balancing, то получим:

  1. Requirements for Installing Oracle Database 19c on OL7 or RHEL7 64-bit (x86-64) (Doc ID 2551169.1)
  2. (EX39) NUMA-enabled database servers experience continuously high load or reduced performance after updating to Exadata 12.2.1.1.0 or higher. (Doc ID 2319324.1)

А также из общедоступных источников: Optimal Configuration of Memory System

https://support.huawei.com/enterprise/en/doc/EDOC1000117211/1395f4a4/optimal-configuration-of-memory-system

Откуда следует вывод, что без kernel.numa_balancing=0 никуда. И действительно, после применения данного параметра, производительность бд значительно выросла:

В итоге, конфигурация имеет значение _log_parallelism_max=2 на уровне бд и kernel.numa_balancing=0 на уровне ОС.

Также эксперимент был проведён на Solaris Sparc:

 Solaris Sparc : 11.4+patch

Oracle 12.1.0.2 + BP

ASM 19.7

И _log_parallelism_max=2 VS_log_parallelism_max=1:

Нагрузка тут уже в 3 раза выше, чем на Linux, а снижение LFS c 0.77 мс до 0.60 мс дало прирост быстродействия на стороне приложения до 30%.

Также _log_parallelism_max=1 снизил потребление ЦПУ на 7%.

Выводов нет, делайте их сами, а использование скрытых параметров должно быть обоснованным и обдуманным решением.