Как замерить время выполнения sql запроса
Иногда требуется понять какая часть в большом скрипте начинает проседать по скорости выполения. Первый вариант — это посмотреть план запроса.
Второй вариант — расставить в скрипте метки времени. Этот вариант и рассмотрим здесь.
Create or ALTER FUNCTION [dbo].[as_sec] -- для вывода в print сколько секунд прошло ( @text as nvarchar(max), @start datetime ) RETURNS varchar(max) AS BEGIN DECLARE @res as nvarchar(max)= cast(cast(DATEDIFF(millisecond,@start,getdate())/1000.0 as decimal(18,2)) as nvarchar) + ' sec - ' + @text RETURN @res END DECLARE @t1 DATETIME = Getdate(); print [dbo].[as_sec] ('start', @t1) select top 400 * from as_trace print [dbo].[as_sec] ('after select 1', @t1) select top 1000 * from as_trace print [dbo].[as_sec] ('after select 2', @t1) select top 20 * from as_trace print [dbo].[as_sec] ('after select 2', @t1) И получаем такой результат:
Таким образом наглядно видно, где возникает основная проблема по времени выполнения скрипта.
Время выполнения SQL запросов
Итак, нам нужно засечь время, потраченное на выполнение SQL запросов ? Это не очень легко, но и не сложно. Начнем с определения задачи. Необходимо выдать полное время, затраченное на генерацию страницы и время, затраченное на выполнения SQL запросов, еще было бы здорово вывести процент от общего времени.
Сначала напишем функцию, которая выдает время, затраченное на выполнение своего кода:
function do_something() < $mtime = microtime(); $mtime = explode(" ",$mtime); $mtime = $mtime[1] + $mtime[0]; $tstart = $mtime; //here is the code to execute //. $mtime = microtime(); $mtime = explode(" ",$mtime); $mtime = $mtime[1] + $mtime[0]; $tend = $mtime; $tpassed = ($tend - $tstart); return($tpassed); >
Для конкретно нашей задачи, нужно модифицировать эту функцию так, чтобы выполнялись SQL запросы:
//запрос передается как аргумент function do_query($query) < //подсоединяем две глобальные переменные global $result; global $qnum; //счетчик запросов $qnum++; //засекаем время старта $mtime = microtime(); $mtime = explode(" ",$mtime); $mtime = $mtime[1] + $mtime[0]; $tstart = $mtime; //выполняем запрос $result = MYSQL_QUERY($query); //засекаем время окончания $mtime = microtime(); $mtime = explode(" ",$mtime); $mtime = $mtime[1] + $mtime[0]; $tend = $mtime; $tpassed = ($tend - $tstart); //возвращаем время, затраченное на запрос return($tpassed); >
Теперь у нас есть функция, которая считает запросы и выдает время экзекуции 🙂 Вот как она должна быть использована:
//Не забудьте где-нибудь в начале скрипта объявить эти две переменные: $result=0; $qnum=0; //. //Вызов функции: $sql_time+=do_query(«SELECT * FROM SOME_TABLE»); //Теперь можно разбирать полученные данные: while($row = mysql_fetch_array($result))
В окончательном скрипте нужно еще засечь полное время выполнения, таким же способом, что использовался в функции. Внизу код такого скрипта, который заработает, если вы вставите реальные SQL запросы и подсоединитесь к базе данных.
//Далее тело скрипта $sql_time+=do_query("SELECT * FROM SOME_TABLE"); //Обрабатываем данные while($row = mysql_fetch_array($result)) < print($row['Text']); >//Пример еще одного запроса $sql_time+=do_query("SELECT * FROM ANOTHER"); //Обрабатываем данные $row = mysql_fetch_array($result); print($row['Another_Text']); //Засекаем время окончания $mtime = microtime(); $mtime = explode(" ",$mtime); $mtime = $mtime[1] + $mtime[0]; $tend = $mtime; $total = ($tend - $tstart); //Выдаем время: printf("SQL запросов: $qnum, время mysql: %f, всего затрачено: %f секунд !", $sql_time, $total); //Вычисляем процент времени: $sqlpercent = ($sql_time*100)/$total; print('Процент времени на MySQL: '. round($sqlpercent, 2) . '%'); ?>
Oracle statistics. Как узнать статистику и время выполнения запроса?
Зачем вообще нужна эта статистика или любые другие показатели? В ходе разработки часто возникает вопрос, а что же быстрее работает? Эффективно ли расходуются ресурсы базы? Если написать код по другому станет ли лучше?
Для ответов на эти вопросы нужно как-то понимать какие ресурсы тратят программы, а самое главное нужна возможность сравнивать разные решения между собой, чтобы отдать предпочтение самому оптимальному способу.
В данной статье не будет рассказано как анализировать показатели, а будет рассказано как их получить.
Описание компонентов
v$mystat
Представление выводит статистику по последней выполненной транзакции в рамках текущей сессии. Состоит из следующих полей:
| Поле | Тип | Описание |
|---|---|---|
| sid | number | идентификатор текущей сессии, полную информацию можно увидеть в v$session |
| statistic# | number | идентификатор значения статистики, ссылается на преставление v$statname |
| value | number | значение статистики |
| con_id | number | идентификатор контейнера (для мультиарендной контейнерной базы данных CDB) |
v$statname
Справочник с описанием значений статистики, нужен для связи с предыдущим представлением. Состоит из следующих полей:
| Поле | Тип | Описание |
|---|---|---|
| statistic# | number | идентификатор значения статистики, ссылается на преставление v$statname |
| name | varchar2(64) | расшифровка значения статистики (постоянное значение) |
| class | number | показывает к какому классу данных относится статистика, ниже описаны возможные значения: 1 — Пользователь 2 — Redo 4 — Постановка в очередь 8 — Кэш 16 — ОС 32 — Реальные Кластеры приложений 64 — SQL 128 — Отладка |
| stat_id | number | идентификатор статистики (в этой статье не понадобится) |
| display_name | varchar2(64) | детальная расшифровка значения статистики (можем меняться с новыми релизами) |
| con_id | number | идентификатор контейнера (для мультиарендной контейнерной базы данных CDB) |
v$timer
Это простое представление, которое возвращает время в сотых долях секунды, мы будет фиксировать время до и после теста, и затем отнимать одно значение от другого. Состоит из двух полей:
| Поле | Тип | Описание |
|---|---|---|
| hsecs | number | количество времени в сотых долях секунды |
| con_id | number | идентификатор контейнера (для мультиарендной контейнерной базы данных CDB) |
dbms_utility.get_cpu_time
Функция, которая возвращает время работы процессора (CPU) в сотых долях секунды.
select dbms_utility.get_cpu_time from dual; —результат 815
Права
Для выполнения представления у пользователя (в моем случае PROD) должен быть доступ на все таблицы, подключаемся к БД с помощью пользователя SYS с ролью SYSDBA и выполняем скрипты ниже:
grant select on v_$statname to prod; grant select on v_$mystat to prod; grant select on v_$timer to prod; grant execute on dbms_utility to prod;
Измерение общего и CPU времени на запрос
Логика простая — мы будем записывать значения времени в переменные до выполнения запроса и после, затем вычитать время завершения от времени начала и получать итоговый результат. Вывод результата будет осуществляться с помощью dbms_output.put_line , чтобы данные выводилилсь в SQL Developer перед выполнением скриптов выполним команду включающую вывод, а затем будет логика.
—включаем вывод данных в output set serveroutput on; declare v_t1 number; —время начала v_t2 number; —время завершения v_cpu1 number; —время ЦПУ до v_cpu2 number; —время ЦПУ после v_t_res number; —общее время выполнения v_cpu_res number; —общее время выполнения CPU begin —фиксируем начало —помещаяем общее время и время ЦПУ в переменные select t.hsecs ,dbms_utility.get_cpu_time into v_t1 ,v_cpu1 from v$timer t; —запустим 1000 раз цикл, который обновит дату у первых попавшихся строк for rec in 1..1000 loop update prod.operation set op_date = trunc(sysdate) where rownum = 1 and op_date != trunc(sysdate); end loop; —фиксируем завершение —снова помещаяем общее время и время ЦПУ в переменные select t.hsecs ,dbms_utility.get_cpu_time into v_t2 ,v_cpu2 from v$timer t; —считаем общее время выполнения в сотых долях секунды v_t_res := v_t2 — v_t1; —считаем общее время ЦПУ в сотых долях секунды v_cpu_res := v_cpu2 — v_cpu1; —выводим результат на экран dbms_output.put_line(‘Общее время выполнения в секундах: ‘||to_char(v_t_res/100,’0.00’)); dbms_output.put_line(‘Общее время ЦПУ в секундах: ‘||to_char(v_cpu_res/100,’0.00’)); —откатим изменения rollback; end;
Результат:
Статистика
Получение статистики по одному запросу
-
Запускаем нужный скрипт, например, изменим ранее сгенерированные данные:
Создание представления для быстрого доступа к данным
Для быстрого доступа к данным, соединим все ранее представленные скрипты по выводу данных по статистки, времени ЦПУ, общему времени и «упакуем» полученный запрос в представление. Вот как это будет выглядеть:
create or replace view prod.stats_vw as —первый скрипт по выводу статистики select ‘STAT’ as inf_type, — для inf_type в stats_tbl a.name as name, — для name в stats_tbl b.value as value — для value в stats_tbl from v$statname a join v$mystat b on a.statistic# = b.statistic# —команда объединения union all —второй скрипт по фиксации общего времени select ‘ETIME’, — сокращенно от Elapsed time (общее время) ‘Elapsed Time’, hsecs from v$timer —команда объединения union all —третий скрипт по фиксации времени CPU select ‘CTIME’, —сокращенно от CPU time (время ЦПУ) ‘CPU Time’, dbms_utility.get_cpu_time from dual;
После создания VIEW, чтобы получить информацию достаточно выполнить простой запрос:
select * from stats_vw;
Результат:
Создание процедуры фиксации статистики
До и после выполнения наших скриптов, нам нужно записывать данные «до» запуска и «после», будем записать результаты с помощью процедуры ниже:
create or replace procedure fix_inf_prc(p_script_num in char, p_run_type in stats_tbl.run_type%type) as —должно получиться например: before1, after2 v_run_type stats_tbl.run_type%type := lower(p_run_type) || p_script_num; —автономная транзакция, чтобы не закоммитить данные запроса pragma autonomous_transaction; begin if p_run_type not in (‘before’, ‘after’) then raise_application_error(-20001 ,’Тип запуска может принимать значения before или after.’ ||p_run_type); end if; —фиксируем информацию добавляя результат выполнения VIEW insert into stats_tbl (run_type, inf_type, name, value) select v_run_type, s.* from stats_vw s; —удаляем старые данные если есть delete from stats_tbl where id in ( select id from ( select row_number() over(partition by name, run_type order by s.id desc) rn ,s.* from stats_tbl s) where rn = 2 —удаляем только старые данные or run_type = ‘final’||p_script_num); —если это замер статистики после, то посчитаем итоговые данные if lower(p_run_type) = ‘after’ then insert into stats_tbl (run_type, inf_type, name, value) select ‘final’||p_script_num , b.inf_type , b.name , a.value-b.value —вычитаем «до» из значения «после» from stats_tbl b join stats_tbl a on a.name = b.name and a.run_type = ‘after’||p_script_num where b.run_type = ‘before’||p_script_num; end if; —фиксируем commit; end;
Пояснение отдельных частей кода:
| Строка | Описание |
|---|---|
| p_script_num in char | первый входной параметр, предназначен для определения номера тестируемого скрипта |
| p_run_type in stats_tbl.run_type%type | второй входной параметр, принимает на вход два значения «before» или «after», тут если мы фиксируем статистику до перед выполнением скрипта указываем «before», если после то соответственно «after» |
| inf_type varchar2(15 char), | для указания типа информации т.е. мы умеем собирать статистику, измерять время ЦПУ и общее время, т.е. 3 разных типа информации, в будущем типы будут добавляться |
| pragma autonomous_transaction; | процедура будет транзакцией, внутри основной транзакции, например, в рамках теста мы сделали update строк и в конце нужно будет отменить изменения, но данные по статистике должны сохраниться |
| select row_number() over(partition by name, run_type order by s.id desc) rn | это для удаления дублей от запусков, например запустим два раза процедуру с параметром «after», будут дублироваться данные, эта функция группирует такие строки и проставляет номера, 1-самая актуальная, 2 — старее. |
| or run_type = ‘final’||p_script_num | это условие, чтобы не дублировались финальные данные |
| on commit preserve rows; | Временные таблицы хранят данные в течение транзакции или в течение сессии, тут указывается, что хранить нужно в течение сессии |
Запустим программу (если будут ошибки, пишите в комментариях), пока результат мы не увидим, но статистику уже запишем:
—тест скрипта №1 begin —фиксируем начало работы fix_inf_prc(1,’before’); —скрипт №1 for rec in 1..100 loop update operation set op_date = trunc(sysdate) where rownum = 1 and op_date != trunc(sysdate); end loop; —фиксируем завершение работы fix_inf_prc(1,’after’); rollback; end; —тест скрипта №2 begin —фиксируем начало работы fix_inf_prc(2,’before’); —скрипт №2 for rec in 1..1000 —увеличим количесто циклов loop update operation set op_date = trunc(sysdate) where rownum = 1 and op_date != trunc(sysdate); end loop; —фиксируем завершение работы fix_inf_prc(2,’after’); rollback; end;
Вывод результатов
Вывод статистики скриптом
Сразу обернем такой селект в VIEW для дальнейшего использования и расширения, также для лучшей читаемости, добавим форматирование для числа, чтобы тысячные доли разделялись запятыми:
create or replace view stats_report_vw as with all_stats as (select f1.inf_type||’. ‘||f1.name name ,f1.value script1 ,f2.value script2 ,(f2.value — f1.value) diff from stats_tbl f1 join stats_tbl f2 on f2.name = f1.name and f2.run_type = ‘final2’ where f1.run_type = ‘final1’) select * from all_stats;
Запускаем созданный VIEW, по желанию добавляем фильтры и сортируем:
select * from stats_report_vw where abs(diff) > 1 —фильтр по полю diff and name like ‘%ime%’ —фильтр по полю name order by abs(diff);
Результат:
Вывод статистики через dbms_output
Создадим процедуру stats_report_prc и на вход будем подавать два фильтра, плюс я выведу отдельно от таблицы со статисткой показатели времени и буду выводить их в секундах:
create or replace procedure stats_report_prc (p_diff_count in number default 0, p_like_name in varchar2 default null, p_sort_field_num in number default 4) is begin —выводим статистику dbms_output.put_line(rpad(‘Name’, 30) || lpad(‘Run1’, 16) || lpad(‘Run2’, 16) || lpad(‘Diff’, 16)); for rec in (select s.name, to_char(s.script1, ‘999G999G999G999’) script1, to_char(s.script2, ‘999G999G999G999’) script2, to_char(s.diff, ‘999G999G999G999’) diff from stats_report_vw s where s.name not like ‘%TIME. %’ —исключаем ETIME, CTIME and abs(s.diff) > p_diff_count —фильтр по величине отличий and (p_like_name is null or lower(s.name) like lower(‘%’|| p_like_name ||’%’)) —фильтр по имени order by p_sort_field_num) loop dbms_output.put_line(rpad(rec.name, 30) || lpad(rec.script1, 16) || lpad(rec.script2, 16) || lpad(rec.diff, 16)); end loop; —добавим отступ dbms_output.put_line(chr(9)); —выводим данные о времени dbms_output.put_line(rpad(‘Name’, 30) || lpad(‘Run1 (sec)’, 16) || lpad(‘Run2 (sec)’, 16) || lpad(‘Diff (sec)’, 16)); for rec in (select s.name, rtrim(to_char(s.script1/100, ‘FM999999999999990.99999’), ‘.’) script1, rtrim(to_char(s.script2/100, ‘FM999999999999990.99999’), ‘.’) script2, rtrim(to_char(s.diff/100, ‘FM999999999999990.99999’), ‘.’) diff from stats_report_vw s where s.name like ‘%TIME. %’) —выводим только ETIME, CTIME loop dbms_output.put_line(rpad(rec.name, 30) || lpad(rec.script1, 16) || lpad(rec.script2, 16) || lpad(rec.diff, 16)); end loop; end;
Запустим отчет и посмотрим что получилось:
set serveroutput on; begin stats_report_prc(1); — выдодить где разница больше 1 end;
Результат:
SET STATISTICS TIME (Transact-SQL)
Отображает время в миллисекундах, необходимое для синтаксического анализа, компиляции и выполнения каждой инструкции.
Синтаксис
SET STATISTICS TIME
Ссылки на описание синтаксиса Transact-SQL для SQL Server 2014 и более ранних версий, см. в статье Документация по предыдущим версиям.
Remarks
После выполнения инструкции SET STATISTICS TIME ON отображается статистика по времени для инструкций. Если указан параметр OFF, статистика по времени не показывается.
Значение параметра STATISTICS TIME устанавливается во время выполнения или запуска, а не во время синтаксического анализа.
В Microsoft SQL Server невозможно предоставить точную статистику в режиме волокон, который активируется при включении параметра конфигурации использование упрощенных пулов.
Столбец cpu в таблице sysprocesses обновляется только во время выполнения запроса с инструкцией SET STATISTICS TIME ON. Если для параметра SET STATISTICS TIME установлено значение OFF, возвращается значение 0.
Настройки ON и OFF влияют на значения в столбце «ЦП» в окне «Просмотр сведений о процессах для текущей деятельности» в среде SQL Server Management Studio.
Разрешения
Для использования инструкции SET STATISTICS TIME пользователи должны иметь разрешения, необходимые для выполнения инструкций языка Transact-SQL. Разрешение SHOWPLAN не требуется.
Примеры
В данном примере показано время выполнения, синтаксического анализа и компиляции сервера.
USE AdventureWorks2022; GO SET STATISTICS TIME ON; GO SELECT ProductID, StartDate, EndDate, StandardCost FROM Production.ProductCostHistory WHERE StandardCost < 500.00; GO SET STATISTICS TIME OFF; GO SQL Server parse and compile time: CPU time = 0 ms, elapsed time = 1 ms. SQL Server parse and compile time: CPU time = 0 ms, elapsed time = 1 ms. (269 row(s) affected) SQL Server Execution Times: CPU time = 0 ms, elapsed time = 2 ms. SQL Server parse and compile time: CPU time = 0 ms, elapsed time = 1 ms.