Kohana, Заметки → Kohana: Bug Report #4638

Вчера в твиттере Иван скинул ссылку, на баг в kohana 3.3 под №4638. В поисках проблеммы, сегодня, убил почти 2 часа времени и все-равно сам бы не нашел корень проблемы. Спасибо хорошему человеку (Трин, привет :)). Давайте по порядку разберем суть проблемы, источник проблемы и ее решение…

ВНИМАНИЕ! На абсолютные цифры не смотрите, смотрите на процентное изменение. По поводу абсолютных цифр выскажусь в конце поста.

Если посмотрите описание бага по ссылке выше, то поймете, что иногда, по каким-то причинам, скорость обработки запроса в kohana 3.3 заметно падает. Там же можно увидеть, что проблема находится в методе send_headers класса Response, который вызывает одноименный метод в классе HTTP_Header, который, в свою очередь, вызывает приват-метод _send_headers_to_php. Вот что находится в последнем:

	protected function _send_headers_to_php(array $headers, $replace)
	{
		// If the headers have been sent, get out
		if (headers_sent())
			return $this;

		foreach ($headers as $key => $line)
		{
			if ($key == 'Set-Cookie' AND is_array($line))
			{
				// Send cookies
				foreach ($line as $name => $value)
				{
					Cookie::set($name, $value['value'], $value['expiration']);
				}

				continue;
			}
			header($line, $replace);
		}

		return $this;
	}

Как видите, ничего сверхъестественного… Чуть заходя вперед, выяснилось — проблема в вызове header($line, $replace). Да, это нативная функция. Нет, изменение второго параметра ничего не даст ))).

Именно на этом месте я и потратил 1.5 часа своей жизни, пока умный человек не сел за мой комп. А дальше он за пару минут нашел саму проблему и ее решение!

Оказалось, что сама проблема кроется не в функции header, а в том, что именно она отправляет! Кто изучал протокол HTTP, скорее всего, уже поняли в чем загвоздка, для остальных объясню. В классе HTTP_Header, в методе send_headers kohana формирует основные заголовки, отправляемые перед заголовками пользователя. В частности, на пустом проекте, формируются 2 заголовка:

1: HTTP/1.1 200 OK
2: Content-Type: text/html; charset=utf-8

Все хорошо, вроде как… Вот только Apache, получив указание использовать протокол HTTP/1.1, автоматически делает соединение с клиентом постоянным. По этой ссылке обратите внимание на следующие строки:

При работе по HTTP 1.1 все соединения считаются постоянными, если не обозначено иное. При этом постоянные соединения не используют сообщения keepalive, а просто позволяют передачу множественных запросов в одном и том же соединении. Тем не менее, время ожидания по умолчанию в httpd для Apache 2.0 составляет всего 15 секунд, а для Apache 2.2 лишь 5 секунд. Преимуществом короткого таймаута является возможность быстрее передать клиенту множественным соединением несколько компонентов веб-страницы, а не более долгим методом инициации нескольких серверных процессов или потоков.

Открываем описание бага в багтрекере и видим: Apache 2.2.22, Time per request: 5554.722 [ms]. Вполне себе соответствует спецификации, верно? 😉

Ну а дальше, уже покопав самостоятельно что и как, стало ясно — это не баг kohana, это не правильное использование Apache Bench, т.к. kohana (по умолчанию) использует протокол HTTP/1.1, то запускать Apache Bench надо бы с ключем -k, т.е., примерно так:

c:\web\server\http\Apache-2.2.21\bin>ab -n100 -c10 -k http://ab.rru/
This is ApacheBench, Version 2.3
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/</code>

Benchmarking ab.rru (be patient).....done

Server Software: Apache/2.2.21
Server Hostname: ab.rru
Server Port: 80

Document Path: /
Document Length: 13 bytes

Concurrency Level: 10
Time taken for tests: 4.291 seconds
Complete requests: 100
Failed requests: 0
Write errors: 0
Keep-Alive requests: 0
Total transferred: 24400 bytes
HTML transferred: 1300 bytes
Requests per second: 23.30 [#/sec] (mean)
Time per request: 429.125 [ms] (mean)
Time per request: 42.912 [ms] (mean, across all concurrent requests)
Transfer rate: 5.55 [Kbytes/sec] received

Connection Times (ms)
min mean[+/-sd] median max
Connect: 10 35 15.2 34 80
Processing: 96 358 98.2 358 786
Waiting: 95 320 109.9 318 786
Total: 125 393 98.8 391 816

Percentage of the requests served within a certain time (ms)
50% 391
66% 425
75% 452
80% 463
90% 487
95% 517
98% 662
99% 816
100% 816 (longest request)

Скорость работы выросла в 13 раз, до 23-27 запросов в секунду. Показатели не фантастические, но намного лучше тех, которые были. (При этом, максимум на локали с die(); в начале index.php — 135 запросов в секунду).

Получается, есть несколько вариантов решения данного бага:
1. Правильно использовать Apache Bench или не удивляться результатам )).
2. Явно указать в kohana использование протокола HTTP/1.0. Для этого, создаем в application/classes файл HTTP.php, примерно следующего содержания:

<?php

class HTTP extends Kohana_HTTP {

	public static $protocol = 'HTTP/1.0';

}

3. Закрывать соединение со стороны сервера при использовании протокола HTTP/1.1. Для этого, создаем в application/classes директорию HTTP, в которой создаем файл Header.php следующего содержания:

<?php

class HTTP_Header extends Kohana_HTTP_Header {

	public function send_headers(HTTP_Response $response = NULL, $replace = FALSE, $callback = NULL)
	{
		if ($response === NULL)
		{
			// Default to the initial request message
			$response = Request::initial()->response();
		}

		$protocol = $response->protocol();
		$status = $response->status();

		// Create the response header
		$processed_headers = array($protocol.' '.$status.' '.Response::$messages[$status]);

		// Get the headers array
		$headers = $response->headers()->getArrayCopy();

		foreach ($headers as $header => $value)
		{
			if (is_array($value))
			{
				$value = implode(', ', $value);
			}

			$processed_headers[] = Text::ucfirst($header).': '.$value;
		}

		if ( ! isset($headers['content-type']))
		{
			$processed_headers[] = 'Content-Type: '.Kohana::$content_type.'; charset='.Kohana::$charset;
		}

		if (Kohana::$expose AND ! isset($headers['x-powered-by']))
		{
			$processed_headers[] = 'X-Powered-By: '.Kohana::version();
		}

		// Get the cookies and apply
		if ($cookies = $response->cookie())
		{
			$processed_headers['Set-Cookie'] = $cookies;
		}

		if ('HTTP/1.1' == $protocol)
		{
			$processed_headers[] = 'Connection: close';
		}

		if (is_callable($callback))
		{
			// Use the callback method to set header
			return call_user_func($callback, $response, $processed_headers, $replace);
		}
		else
		{
			$this->_send_headers_to_php($processed_headers, $replace);
			return $response;
		}
	}

}

Есть еще идеи, как обойти данную особенность (это не баг!все-таки баг разработчиков kohana)?

Теперь, что касается абсолютных значений. Все значения выше (как и сам баг) у меня получались на локальной машине под управлением Win7x64. На сервере, под CentOS, я так и не смог поймать подобную проблему и цифры там стабильные — 230-270 запросов с сек. Есть подозрение, что под виндой Apache Bench работает совсем иначе, чем под *nix, либо сам Apache работает значительнее медленее.

Update 04.01.2013: сегодня снова столкнулся с данной проблемой (точнее, с другой, но корни одни). Пришлось покопаться чуть дольше, но и выяснилось чуть больше. Данная проблема — это баг разработчиков kohana. В kohana 3.2, при создании объекта Response в конструктор передавался протокол из запроса, в результате в Response использовался точно такой-же протокол, как в Request. А в kohana 3.3 я подобного кода не нашел. Забыли? Мало вероятно, но бывает всякое…

В данный момент спасает добавление строки

$this->response->protocol($this->request->protocol());

В метод before базового контроллера сразу от 2-х проблем: описанной в данном посту и от проблемы появления лишних символов перед выводом страницы (подробнее на офф.форуме, кстати именно второй баг и ссылка в комментариях к нему подсказала что и где искать). На данный момент это единственно верное решение, все варианты выше — костыли, НЕ ИСПОЛЬЗУЙТЕ ИХ!