Blog Relocated

Oops, Блог переехал. http://mairbek.github.com/blog.html

Logging Gotcha

Любое мало-мальски уважающее себя приложение не обходится без логгирования. Конечно, ведь иначе работа аппликухи в продакшне превращается в черный ящик.

Современные библиотеки позволяют сохранять информацию на различных уровнях логгирования. В проектах, в которых я участвовал, обычно используется четыре уровня логгирования:

ERROR -- сюда выводится информация о критичных ошибках в системе.
WARN -- используется для вывода не критичных, но все же некорректных сиптомов неправльной работы приложения
INFO -- используется для вывода интересных событий происходлящих в системе
DEBUG -- детальныая информация о том, что происходит с системой. обычно используется при разработке либо при отладке.

Обычно запись в лог выглядит довольно просто:

	log.error("SOMETHING REALLY BAD HAPPENED")
	log.warn("Something bad happened")
	log.info("Startup")
	log.debug("Processing request" + request)

view raw logging.java hosted with ❤ by GitHub

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

До сих пор, строки кода в open source библиотеках вида:

	if (log.isDebugEnabled()) {
	log.debug("Processing request" + request);
	}

view raw logging.java hosted with ❤ by GitHub

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

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

Очень часто во время вывода в debug строки конкатенируются. И конкатенируются они независимо от того влючен дебаг или нет. Это во-первых приводит к тому, что создаются лишние строки что приводит к большим вызовам GC.
Во-вторых, операция toString может занимать продолжительное количество времени, и как показала недавняя история до 15% времени тормозящего метода.

Получается писать проверку влюченности уровня необходимо. Но не удонбно. Количество строчек кода для записи в лог увеличивается в три раза.

Однако, если в проекте используется библиотека логирования slf4j, можно обойтись малой кровью используя шаблоны в строках. Как это работает:

Вместо конкатенации строк при логировании

log.debug("Processed request " + request + " sending response " + response);

view raw oldstyle.java hosted with ❤ by GitHub

писать

log.debug("Processed request {} sending response {}", request, response);

view raw newstyle.java hosted with ❤ by GitHub

Microbenchmarking with Caliper

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

Чаще всего, конечно, можно воспользоваться гуглом, задать вопрос на stackoverflow, но в некоторых ситуациях ничего не остается, кроме как провести эксперименты самому.

Такая инженерная практика именуется microbenchmarking. Суть микробенчмаркинга в измерении производительности (загрузки процессора, памяти или операций с сетью, диском) небольших кусков кода для того, чтобы понять какой код лучше подходит для текущего сценария.

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

Зная что нужно измерять, написать бенчмарк довольно тривиально, и, часто, вполне можно обойтись одним единственным статическим методом main. Однако, используя фреймверк Caliper от компании Google, бенчмарки можно писать быстро и с удовольствием, выкинув при этом кучу boilerplate кода.

API Caliper в чем то напоминает старую версию JUnit. Для того чтобы написать простой бенчмарк нужно:

1. Отнаследоваться от класса com.google.caliper.SimpleBenchmark.
2. Написать тестовые методы, название которых начинается со слова time.
3. Подготовка данных и очистка ресурсов происходит в методах setUp и tearDown соответственно.

Caliper изначально поставляется с большим количеством примеров. Один из интересных LoopingBackwardsBenchmark, который сравнивает скорость итерирования вперед и назад.

	public class LoopingBackwardsBenchmark extends SimpleBenchmark {
	@Param({"2", "20", "2000", "2000000", "20000000", "200000000"})
	private int max;
	public int timeForwards(int reps) {
	int dummy = 0;
	for (int i = 0; i < reps; i++) {
	for (int j = 0; j < max; j++) {
	dummy += j;
	}
	}
	return dummy;
	}
	public int timeBackwards(int reps) {
	int dummy = 0;
	for (int i = 0; i < reps; i++) {
	for (int j = max - 1; j >= 0; j--) {
	dummy += j;
	}
	}
	return dummy;
	}
	public static void main(String[] args) throws Exception {
	Runner.main(LoopingBackwardsBenchmark.class, args);
	}
	}

view raw gistfile1.java hosted with ❤ by GitHub

Запустив тест мы убедимся, что разницы в производительности нет.

Еще один пример. Допустим, мы разрабатываем функциональность которая предполагает огромное количество операций над дробными числами, и мы думаем стоит ли использовать BigDecimal или лучше остановить свой выбор на старом добром быстром double. Сравнить насколько медленней будет работать BigDecimal для такой операции как умножение не сложно.

	public class DoubleVsBigDecimalBenchmark extends SimpleBenchmark {
	@Param({"1", "1.01", "1.0123456789", "20", "20.01", "20.0123456789", "1000000000", "1000000000.01", "1000000000.0123456789"})
	private double value;
	private BigDecimal[] bigDecimalVal = new BigDecimal[1];
	private double[] doubleVal = new double[1];
	@Override
	protected void setUp() throws Exception {
	bigDecimalVal[0] = BigDecimal.valueOf(value);
	doubleVal[0] = value;
	}
	public void timeDouble(int reps) {
	double dummy = 0;
	for (int i = 0; i < reps; i++) {
	int v = i / (reps + 1);
	dummy = doubleVal[v] * doubleVal[v];
	}
	doubleVal[0] = dummy;
	}
	public void timeBigDecimal(int reps) {
	BigDecimal dummy = BigDecimal.ZERO;
	for (int i = 0; i < reps; i++) {
	int v = i / (reps + 1);
	dummy = bigDecimalVal[v].multiply(bigDecimalVal[v]);
	}
	bigDecimalVal[0] = dummy;
	}
	public static void main(String[] args) {
	Runner.main(DoubleVsBigDecimalBenchmark.class, new String[]{});
	}
	}

view raw gistfile1.java hosted with ❤ by GitHub

Прогнав тест, становится видно, что для небольших чисел и чисел с небольшой дробной частью BigDecimal работает в 5 раз медленней, а для больших чисел либо чисел с большим количеством символов после запятой в 20 раз.

Следует заметить, что JVM хитрая штука, и постоянно занимается оптимизацией кода, что сказывается на результатах бенчмарка, по-этому иногда надо выкручиваться. Например, в бенчмарке DoubleVsBigDecimalBenchmark используется массив и странный способ инициализации переменной v нулем.

Читая Practical Clojure

Объектно-ориентированный подход несомненно лучше процедурного, однако не лишен недостатков. Цитата из Practical Clojure:

For the last decade, at least, the object-oriented style has dominated computer programming through its promises of data abstraction, code reuse, encapsulation, and modularity. It has delivered on these with varying levels of success, and is no doubt an improvement over the sequential or procedural styles that preceded it. But a number of problems have also become apparent:

• An object’s mutable state is unmanageable and dangerous in a highly concurrent environment.

• It doesn't really solve the problems of code abstraction and modularization. It is just as easy to write over-dependent “spaghetti” code in an object-oriented language as any other. It still takes skill and special effort to write code that can truly be used without problems in a variety of environments.

• Inheritance is fragile and can be dangerous. Increasingly, even experts in object- oriented languages are discouraging its use.

• It encourages a high degree of ceremony and code bloat. Simple functionality in Java can require several interdependent classes. Efforts to reduce close coupling through techniques like dependency injection involve even more unnecessary interfaces, configuration files, and code generation. Most of the bulk of a program is not actual program code, but defining elaborate structures to support it. 

Hadoop Day at Dev Time

25 октября состоится Hadoop Day в рамках Dev Time, где я буду выступать с докладом о Apache Zookeeper

QA-Club

Вчера прошел мой доклад в рамках QA-club. Спасибо организаторам за предоставленную возможность выступить. Итак все материалы по докладу:

Презентация

slideshare

Пример

qa-club-demo

Для работы проекта необходима подтянуть следующие библиотеки ScalaMate (позволяет использовать dependency injection в scala test), webelement-wrappers (позволяет убодно работать с html элементами).

Ссылки для дальнейшего ознакомления

BDD:

wikipedia

scalatest

rspec

Dependency Injection:

Рекомендую посмотреть видео

guiceberry

Code Review

Удобная система для Code Review rietveld

Видео от разработчика

DVCS

http://nvie.com/posts/a-successful-git-branching-model/

Мой доклад на qa-club

http://www.qaclub.com.ua/node/126

Приходите