ASH - it is a time to rethink what is inside

Пост обновлен  18.07.2014

После публикации первого поста о возможности анализа данных ASH с помощью Tableao, я получил весьма смешной комментарий, что я открыл для себя ASH. Помимо того, что это правда, такое же открытие в этом году сделали и некоторые весьма уважаемые сотрудники Oracle.

Убедительно прошу вас просмотреть одну из лучших презентаций на тему ASH, сделанную в этом году на RMOUG. (на секундочку, это rocky montains oracle users group, и вообще то материалы доступны только участникам. Но поскольку именно эта презентация сделана сотрудниками Oracle, ее выложили. Кстати, если посмотреть на сайт rmoug сразу понятно как должна выглядеть Users Group).

В презентации много интересного, но самое вкусное начинается после слайда "The ASH Fix-up Mechanism". Там рассказывается, как посчитать правильно latency. Большинство людей предполагало, что это avg (time_waited) where time_waited > 0 и можно найти даже книги по Oracle performance с такой формулой.


Все очень просто - запускаем SwingBench, где soe tablespace находится на отдельном устройстве и попробуем определить latency для db file sequential read.

Для контроля, будем использовать несколько источников данных, AWR, и операционную систему.

>iostat -xkd 1 | awk '{ if ($1 != "" &&  $1!="Device:" && $1!="Linux") print strftime("%d/%m/%y %H:%M:%S",systime()),$1,$11 | "tee  iostat.dat" ;}'
и после окончания нагрузки 
>grep sde iostat.dat  | awk '{sum+=$4} END { print "Average = ",sum/NR}'


Результат - 2.6 ms

Теперь AWR - 2 ms. хо-хо - база данных считает, что она читала быстрее чем отдавал диск. Есть несколько объяснений, почему может быть такое, но в целом данные сходятся.

 Тестируем магическую формулу из презентации

Точнее, чем AWR - что не удивительно, поскольку в ASH просто больше данных.

Ну и наконец, посмотрим что нам дает нерекомендованный способ:

Update 1. Это конечно же 5.4 ms. - у меня плохо с операциями деления.

Фантастические данные, но к сожалению не имеющие отношения к реальности.

Мне сложно прямо сходу назвать причину, но если рассмотреть сырые данные, то можно увидеть, что только 1 из многих записей имеет реальное значение порядка 1.6 ms.

В комментариях Игорь обратил внимание что максимум -  1.6 sec, минимум 4.6 ms. Понятно, что одна операция ввода-вывода не может длиться 1 sec - у меня локальные ssd диски. С другой стороны, если это было чтение индекса, операций было много, время которое было затрачено, проставлено только в последней - тогда вроде бы все встает на свои места. Число операций, которые в сумме дали нам 1.6 остается нам неизвестным, посколько были очень короткие, и sample на них просто не попали.



Согласно описанию, по крайне мере как я его понимаю, поскольку все чтения диска длятся очевидно меньше 1 s, time_waited отражает просто момент времени на который пришелся sample. Фактически, мы получим все возможные распределения от 0 до 2.6 ms (которое,  по видимому, отражает реальность).


Вот еще картинка из dba_hist_event_histogram. Oracle считает что да, были события по 2 ms.

Пусть очень мало, но все таки было. Хотя мне кажется, что это что то с аккуратностью сбора  статистики.












PS
Я  разговаривал с одним DBA, который занимается исключительно performance tuning в своей  компании. Так вот, вся команда PT не имеет доступа к production systems. Они могут только запрашивать данные, на основании которых давать свое заключение. Честно говоря, первый раз о таком услышал, что внутри компании такие ограничения. Но вот эта группа не очень чувствует чем им может помочь ASH - они больше ориентируются на AWR, что явно не лучший способ в наше время!