Дмитрий Елисеев
о разработке сайтов и сервисов
Дмитрий Елисеев » Блог » Программирование » Отладочный таймер и пример интеграции в Yii

Отладочный таймер и пример интеграции в Yii

Песочные часы

Довольно часто возникает необходимость проследить время исполнения некоторых фрагментов программного кода? чтобы найти особо медленные участки для их последующей оптимизации. Имеющиеся отладочные расширения не проникают внутрь ваших файлов, а чаще выводят только общее время выполнения скрипта. Для локального рефакторинга и оптимизации они не подходят.

Для вывода текущего времени исполнения в Yii можно расставить в любое место кода строки

echo sprintf('%0.3f',Yii::getLogger()->getExecutionTime());

Этот код выведет число миллисекунд, прощедших с начала выполнения скрипта.

Для упрощения вставки таких «датчиков» в код можно написать простой класс

class DTimer
{
    protected static $startTime;
    protected static $points = array();
 
    public static function run()
    {
        self::$startTime = microtime(true);
    }
 
    public static function log($message='')
    {
        if (self::$startTime === null)
            self::run();
 
        self::$points[] = array('message'=>$message, 'time'=>sprintf('%0.3f', microtime(true) - self::$startTime));
    }
 
    public static function show()
    {
        $oldtime = 0;
 
        echo '
            <table style="width:auto !important; position:fixed; right:0; top:0; z-index:200; background:#fff !important">
             <tr>
                <th></th>
                <th>Diff</th>
                <th>Time</th>
            </tr>
        ';
 
        foreach(self::$points as $item){
 
            $message = $item['message'];
            $time = $item['time'] * 1000;
            $diff = ($item['time'] - $oldtime) * 1000;
 
            echo "
                <tr>
                    <td>{$message}</td>
                    <td style='text-align:right; width:50px'>{$diff}</td>
                    <td style='text-align:right; width:50px''>{$time}</td>
                </tr>
            ";
 
            $oldtime = $item['time'];
        };
        echo "</table>\n";
    }
}

и запустить его в файле index.php:

require_once('DTimer.php');
DTimer::run();

Теперь можно расставить по коду контрольные точки

DTimer::log('start');
$this->superCommand1();
DTimer::log('Command1');
 
$this->superCommand2();
 
// чтобы не учитывать время исполнения superCommand2() 
// поставим здесь ещё одну точку
DTimer::log('reset');
$this->superCommand3();
DTimer::log('Command3');

и после выполнения скрипта вывести таблицу с результатами

DTimer::show();

Таблица появится в правом верхнем углу окна. Она покажет прошедшие интервалы и общее время для каждого вызова:

Diff Time
start 10 10
Command1 9 19
reset 12 31
Command3 18 49

А теперь небольшая хитрость. Если точек нужно много, но лень указывать метки вручную, то можно использовать автоподстановку номеров строк значением __LINE__:

DTimer::log(__LINE__);
$this->superCommand1();
DTimer::log(__LINE__);
$this->superCommand2();
DTimer::log(__LINE__);
$this->superCommand3();
DTimer::log(__LINE__);
$this->superCommand4();
DTimer::log(__LINE__);
$this->superCommand5();
DTimer::log(__LINE__);
$this->superCommand6();
DTimer::log(__LINE__);

Аналогично можно пофантазировать и использовать другие константы (напрмер __METHOD__, __CLASS__).

Применение таймера в Yii

Теперь мы знаем, как можно расставлять контрольные точки в код и отслеживать их прохождение в любом скрипте. Рассмотрим теперь возможность удобно следить за временем выполнения в Yii Framework.

Подключим и запустим наш таймер в начале файла index.php:

require_once('DTimer.php');
DTimer::run();

Теперь дополним наш базовый контроллер. Чтобы засечь момент времени перед выполнением действия (action) контроллера переопределим метод beforeAction(). Классический action оканчивается рендерингом представления, поэтому добавим контрольную точку и в beforeRender():

class Controller extends CController
{
    // ...
 
    protected function beforeAction($action)
    {
        DTimer::log('system');
        return parent::beforeAction($action);
    }
 
    protected function beforeRender($viev)
    {
        DTimer::log('action');
        return parent::beforeRender($viev);
    }
 
}

Таким образом, по этим двум точкам мы уже можем отслеживать время инициальзации фреймворка и время работы экшена.

Для получения более полной информации нам нужно залезть внуть метода CController::render(). Скопируем этот метод из класса CController в наш контроллер и расставим в нём контрольные точки. Также перенесём в него точку DTimer::log('action') и уберём за ненадобностью опустевший метод beforeRender():

class Controller extends CController
{
    // ...
 
    protected function beforeAction($action)
    {
        DTimer::log('system');
        return parent::beforeAction($action);
    }
 
    public function render($view,$data=null,$return=false)
    {
        DTimer::log('action');
 
        if($this->beforeRender($view))
        {
            DTimer::log('beforeRender');
 
            $output=$this->renderPartial($view,$data,true);
            DTimer::log('render');
 
            if(($layoutFile=$this->getLayoutFile($this->layout))!==false){
                $output=$this->renderFile($layoutFile,array('content'=>$output),true);
                DTimer::log('renderLayout');
            }
 
            $this->afterRender($view,$output);
            DTimer::log('afterRender');
 
            $output=$this->processOutput($output);
            DTimer::log('processOutput');
 
            if($return)
                return $output;
            else {
                echo $output;
                DTimer::show();
            }
        }
    }
}

Чтобы таблица диагностики не выскакивала на рабочем сайте можно добавить условие для вывода только в режиме отладки:

else {
    echo $output;
    if (YII_DEBUG) 
        DTimer::show();
}

На этом всё. Теперь мы видим, сколько времени занимает каждый этап и знаем, где именно нужно проводить оптимизацию:

Diff Time
system 67 67
action 17 84
beforeRender 2 86
render 60 146
renderLayout 64 210
afterRender 0 210
processOutput 1 211

Кроме того, «датчики» можно расставлять в любом месте кода (иногда полезно проверить виджеты, модели, поведения и т.д.). Чтобы не заблудиться можно использовать запись

DTimer::log(__METHOD__ . ' ' . __LINE__);

Все «показания» появятся в таблице по порядку их следования в коде.

Комментарии

 

Виталий Сиротенко

Yii::beginProfile
Yii::endProfile
не то?

Ответить

 

Дмитрий Елисеев

То. Но это только в Yii.

Ответить

 

Виталий Сиротенко

просто пример для Yii был, я добавил этот класс в проект на Yii
а потом нашел для себя
Yii::beginProfile
Yii::endProfile
и решил с вами поделиться :)

ps спасибо за отличные уроки по Yii вашем на сайте

можно задать вам вопрос по Yii но не по этой теме, второй день бьюсь?

Ответить

 

Дмитрий Елисеев

Можно. Отправьте через обратную связь.

Ответить

 

Александр Котенко

Здравствуйте. Как можно использовать данную функцию для отслеживания полной загрузки страницы (сайта) глобально. как например видно в дебаг панеле. И вообще можно ли как-то получать информацию из дебага при этом не показывая его пользователю. Спасибо.

Ответить

 

Дмитрий Елисеев

Можно записывать в файлы и отображать в админке.

Ответить

Оставить комментарий

Войти | Завести аккаунт | Войти через


(никто не увидит)





Можно использовать теги <p> <ul> <li> <b> <i> <a> <pre>