Предистория
Как-то раз я занимался оптимизацией сложной операции,
выполняемой на сервере, которая включала в себя несколько запросов
к базе данных с последующей группировкой и сортировкой по определенным
параметрам полученных данных. К сожалению, средствами SQL запросов
обойтись не получилось, так как в конечной выборке участвовали
данные полученные по веб-сервисам из внешних систем. Поэтому приходилось
выполнять группировку и сортировку данных с помощью кода приложения.
Когда я запустил первый раз этот код на реальных
данных, очевидно, все работало неприемлемо медленно и требовало
оптимизации. С чего начинать оптимизацию? Правило Парето никто
не отменял и оно гласит, что нужно начинать оптимизацию тех участков
кода, выполнение которых занимает львиную долю времени выполнения
операции. Возникла задача выяснить, какой из этапов крупной операции
выполняется дольше остальных, и насколько дольше. Для этого необходимо
"стоять с секундомером" и засекать начало и конец каждого этапа и
результат выводить в лог. На момент решения данной задачи я обошелся
собственным решением, в котором я запоминал System.currentTimeMillis()
в промежуточные значения в локальных переменных. Затем происходил
подсчет разниц времени вывод в лог описаний. У данного подхода я
обнаружил существенные недостатки:
- Код сильно загрязнился. Локальные переменные заполонили код, и его стало читать очень сложно.
- Сложно исправлять/добавлять новую операцию, так как логика о подсчету времени размазана.
Но есть и плюс, только он на мой взгляд один: это гибкость и возможность написать то, что тебе нужно.
Что рассмотрим
Поискав в интернете на эту тему, я решил остановиться на рассмотрении 3-х реализаций секнудомеров.
- GUAVA Stopwatch.
- Apache Commons Lang StopWatch.
- Spring Framework StopWatch.
Сравнивать реализации секундомеров будем на
одном и том же фрагменте кода, в котором выполняется длительная операция
состоящая из набора меньших операций. Код исходного класса представлен
ниже:
package ru.egrik.stopwatch;
import java.util.Random;
/**
* Очень сложная составная операция.
*
* @author echernyshev
* @since 12 авг. 2013 г.
*/
public class VeryDifficultOperation
{
/**
* Точка входа в операцию
*/
public void execute()
{
step1();
step2();
compositeStep3();
}
/**
* Шаг 1
*/
private void step1()
{
waitRandomDelay();
}
/**
* Шаг 2
*/
private void step2()
{
waitRandomDelay();
}
/**
* Сложный составной шаг 3
*/
private void compositeStep3()
{
step31();
step32();
step33();
}
/**
* Первая часть шага 3
*/
private void step31()
{
waitRandomDelay();
}
/**
* Вторая часть шага 3
*/
private void step32()
{
waitRandomDelay();
}
/**
* Первая часть шага 3
*/
private void step33()
{
waitRandomDelay();
}
private void waitRandomDelay()
{
Random rmd = new Random();
int randomDelay = rmd.nextInt(3000);
try
{
Thread.sleep(randomDelay);
}
catch (InterruptedException e)
{
e.printStackTrace();
System.exit(1);
}
}
public static void main(String[] args)
{
VeryDifficultOperation operation = new VeryDifficultOperation();
operation.execute();
}
}
GUAVA Stopwatch
Для сборки проектов я использую Maven. Чтобы включить Guava в проект пропишем зависимость в pom.xml:<dependency>
<groupId>com.google.guava</groupId>
<artifactId>guava</artifactId>
<version>19.0</version>
</dependency>- start() - старт секундомера;
- stop() - остановка секундомера;
- reset() - сброс секундомера.
- elapsed(TimeUnit u) - получить прошедшее время в java.util.concurrent.TimeUnit единицах.
- toString() - получить строковое представление.
package ru.egrik.stopwatch;
import java.util.Random;
import java.util.concurrent.TimeUnit;
import com.google.common.base.Stopwatch;
/**
* Очень сложная составная операция.
*
* @author echernyshev
* @since 12 авг. 2013 г.
*/
public class VeryDifficultOperationGuavaStopwatch
{
/**
* Точка входа в операцию
*/
public void execute()
{
Stopwatch sw = Stopwatch.createUnstarted();
System.out.println("Start Step1 at " + sw);
sw.start();
step1();
long step1Elapsed = sw.elapsed(TimeUnit.MILLISECONDS);
System.out.println("Step1 completed for " + step1Elapsed + "ms");
System.out.println("Start Step2 at " + sw);
step2();
long step2Elapsed = sw.elapsed(TimeUnit.MILLISECONDS) - step1Elapsed;
System.out.println("Step2 completed for " + step2Elapsed + "ms");
System.out.println("Start Step3 at " + sw);
compositeStep3(sw);
sw.stop();
long operationElapsed = sw.elapsed(TimeUnit.MILLISECONDS);
long step3Elapsed = sw.elapsed(TimeUnit.MILLISECONDS) - step2Elapsed;
System.out.println("Step3 completed for " + step3Elapsed + "ms");
StringBuffer summary = new StringBuffer("===\nOperation summary:\n")
.append("Operation completed for " + operationElapsed + "ms\n")
.append("Step1 for " + step1Elapsed + "ms ["+ String.format("%.2f", step1Elapsed / (double) operationElapsed * 100) + "%]\n")
.append("Step2 for " + step2Elapsed + "ms ["+ String.format("%.2f", step2Elapsed / (double) operationElapsed * 100) + "%]\n")
.append("Step3 for " + step3Elapsed + "ms ["+ String.format("%.2f", step3Elapsed / (double) operationElapsed * 100) + "%]\n")
.append("===");
System.out.println(summary.toString());
}
/**
* Шаг 1
*/
private void step1()
{
waitRandomDelay();
}
/**
* Шаг 2
*/
private void step2()
{
waitRandomDelay();
}
/**
* Сложный составной шаг 3
*/
private void compositeStep3(Stopwatch sw)
{
System.out.println("Start Step31 at " + sw);
long before = sw.elapsed(TimeUnit.MILLISECONDS);
step31();
long step31Elapsed = sw.elapsed(TimeUnit.MILLISECONDS) - before;
System.out.println("Step31 completed for " + step31Elapsed + "ms");
System.out.println("Start Step32 at " + sw);
step32();
long step32Elapsed = sw.elapsed(TimeUnit.MILLISECONDS) - before;
System.out.println("Step32 completed for " + step32Elapsed + "ms");
System.out.println("Start Step33 at " + sw);
step33();
long step33Elapsed = sw.elapsed(TimeUnit.MILLISECONDS) - before;
System.out.println("Step33 completed for " + step33Elapsed + "ms");
}
/**
* Первая часть шага 3
*/
private void step31()
{
waitRandomDelay();
}
/**
* Вторая часть шага 3
*/
private void step32()
{
waitRandomDelay();
}
/**
* Первая часть шага 3
*/
private void step33()
{
waitRandomDelay();
}
private void waitRandomDelay()
{
Random rmd = new Random();
int randomDelay = rmd.nextInt(3000);
try
{
Thread.sleep(randomDelay);
}
catch (InterruptedException e)
{
e.printStackTrace();
System.exit(1);
}
}
public static void main(String[] args)
{
VeryDifficultOperationGuavaStopwatch operation = new VeryDifficultOperationGuavaStopwatch();
operation.execute();
}
}
Start Step1 at 0,000 ns
Step1 completed for 1425ms
Start Step2 at 1,425 s
Step2 completed for 1021ms
Start Step3 at 2,446 s
Start step31 at 2,447 s
step31 completed for 1468ms
Start step32 at 3,915 s
step32 completed for 4389ms
Start step33 at 6,836 s
step33 completed for 6175ms
Step3 completed for 7600ms
===
Operation summary:
Operation completed for 8621ms
Step1 for 1425ms [16,53%]
Step2 for 1021ms [11,84%]
Step3 for 7600ms [88,16%]
===
Видим, что читаемость кода ухудшилась, не
хватает инкапсуляции переменных, которые хранят в себе засечки времени
каждого этапа. По сути этот код практически ничем не лучше кода, который
я написал с засеканием времени через System.currentTimeMillis().
Еще один существенный недостаток - это то, что класс объявлен как final
и его нельзя дописать под свои нужды. Из плюсов хочется отметить то,
что время можно засекать с точностью до наносекунд. Остальные
рассматриваемые секундомеры засекают время с точностью до милисекунды.
Таким образом, GUAVA Stopwatch
применим в случаях, когда операции выполняются быстрее одной
милисекунды, и в простых случаях использования секундомеров, когда
больше одного интервала засекать не нужно.
Apache Commons Lang StopWatch
Чтобы включить Apache Commons Lang в проект пропишем зависимость в pom.xml:
<dependency>
<groupId>commons-lang</groupId>
<artifactId>commons-lang</artifactId>
<version>2.6</version>
</dependency>
Секундомер реализован в классе org.apache.commons.lang.time. StopWatch . Для старта секундомера нужно вызвать метод start(). После этого возможны следующие действия с секундомером:
- split() - остановка секундомера для того, чтобы посмотреть сколько прошло времени, пока секундомер продолжает идти в фоне. Метод unsplit() - снимает эффект метода split(). С момента вызова unsplit() доступны для вызова снова три перечисленных действия.
- suspend() - приостановка секундомера. Метод resume() возобновляет работу секундомера. Время между вызовами suspend() и resume() не учитывается. С момента вызова resume() доступны для вызова снова три перечисленных действия.
- stop() - останавливает секундомер.
- getTime() - получить прошедшее время в милисекундах.
- toString() - получить строковое представление.
package ru.egrik.stopwatch;
import java.util.Random;
import org.apache.commons.lang.time.StopWatch;
/**
* Очень сложная составная операция.
*
* @author echernyshev
* @since 12 авг. 2013 г.
*/
public class VeryDifficultOperationApacheStopWatch
{
/**
* Точка входа в операцию
*/
public void execute()
{
StopWatchsw = new StopWatch();
System.out.println("Start Step1 at " + sw);
sw.start();
step1();
sw.split();
long step1Elapsed = sw.getSplitTime();
System.out.println("Step1 completed for " + step1Elapsed + "ms");
System.out.println("Start Step2 at " + sw);
sw.unsplit();
step2();
sw.split();
long step2Elapsed = sw.getSplitTime() - step1Elapsed;
System.out.println("Step2 completed for " + step2Elapsed + "ms");
System.out.println("Start Step3 at " + sw);
sw.unsplit();
compositeStep3(sw);
sw.stop();
long operationElapsed = sw.getTime();
long step3Elapsed = sw.getTime() - step2Elapsed;
System.out.println("Step3 completed for " + step3Elapsed + "ms");
StringBuffer summary = new StringBuffer("===\nOperation summary:\n")
.append("Operation completed for " + operationElapsed + "ms\n")
.append("Step1 for " + step1Elapsed + "ms ["+ String.format("%.2f", step1Elapsed / (double) operationElapsed * 100) + "%]\n")
.append("Step2 for " + step2Elapsed + "ms ["+ String.format("%.2f", step2Elapsed / (double) operationElapsed * 100) + "%]\n")
.append("Step3 for " + step3Elapsed + "ms ["+ String.format("%.2f", step3Elapsed / (double) operationElapsed * 100) + "%]\n")
.append("===");
System.out.println(summary.toString());
}
/**
* Шаг 1
*/
private void step1()
{
waitRandomDelay();
}
/**
* Шаг 2
*/
private void step2()
{
waitRandomDelay();
}
/**
* Сложный составной шаг 3
*/
private void compositeStep3(StopWatch sw)
{
System.out.println("Start Step31 at " + sw);
long before = sw.getTime();
step31();
sw.split();
long step31Elapsed = sw.getSplitTime() - before;
System.out.println("Step31 completed for " + step31Elapsed + "ms");
System.out.println("Start Step32 at " + sw);
sw.unsplit();
step32();
sw.split();
long step32Elapsed = sw.getSplitTime() - before;
System.out.println("Step32 completed for " + step32Elapsed + "ms");
System.out.println("Start Step33 at " + sw);
sw.unsplit();
step33();
sw.split();
long step33Elapsed = sw.getSplitTime() - before;
System.out.println("Step33 completed for " + step33Elapsed + "ms");
}
/**
* Первая часть шага 3
*/
private void step31()
{
waitRandomDelay();
}
/**
* Вторая часть шага 3
*/
private void step32()
{
waitRandomDelay();
}
/**
* Первая часть шага 3
*/
private void step33()
{
waitRandomDelay();
}
private void waitRandomDelay()
{
Random rmd = new Random();
int randomDelay = rmd.nextInt(3000);
try
{
Thread.sleep(randomDelay);
}
catch (InterruptedException e)
{
e.printStackTrace();
System.exit(1);
}
}
public static void main(String[] args)
{
VeryDifficultOperationApacheStopWatch operation = new VeryDifficultOperationApacheStopWatch();
operation.execute();
}
}
Start Step1 at 0:00:00.000
Step1 completed for 2236ms
Start Step2 at 0:00:02.236
Step2 completed for 2961ms
Start Step3 at 0:00:05.197
Start Step31 at 0:00:05.197
Step31 completed for 850ms
Start Step32 at 0:00:06.047
Step32 completed for 2205ms
Start Step33 at 0:00:07.402
Step33 completed for 4517ms
Step3 completed for 6753ms
===
Operation summary:
Operation completed for 9714ms
Step1 for 2236ms [23,02%]
Step2 for 2961ms [30,48%]
Step3 for 6753ms [69,52%]
===
Таким образом, Apache Commons Lang StopWatch практически такой-же как и GUAVA Stopwatch ,
Единственное отличие - это наличие методов split() и unsplit(). Сколько
я не думал, я не понял зачем нужны эти методы. Так как мы можем всегда
взять текущее время секундомера через метод getTime() зачем его
останавливать мне не понятно. Возможно это сделано для того, чтобы мы
могли зафикировать конец операции в одном месте, а использовать
getSplitTime намного позже. В моей задаче это приемущество не
использовалось. Из плюсов отмечу то, что можно написать наследника
данного класса доопределив в нем нужный функционал.
Spring Framework StopWatch
Если вдруг так получилось, что в проекте над которым Вы работаете используется Spring, то Вы можете использовать реализацию секундомера из библиотеки spring-core. Подключаем через maven зависимость:
<dependency>
<groupId>org.springframework</groupId>
<artifactId>spring-core</artifactId>
<version>4.0.6.RELEASE</version>
</dependency>- start(String taskName) - старт задачи с определенным именем.
- stop() - остановка текущей задачи. Во время остановки - запоминается время, которое выполнялась задача.
Для вывода состояний секундомера есть 3 способа:
- shortSummary() - краткая информация о текущем времени.
- toString() - shortSummary() + имена всех задач с их временем выполнения и процентом от общего времени.
- prettyPrint() - shortSummary() + красивый вывод таблицы с задачами, их временем выполнения, и процентом от общего времени.
package ru.egrik.stopwatch;
import java.util.Random;
import org.springframework.util.StopWatch
/**
* Очень сложная составная операция.
*
* @author echernyshev
* @since 12 авг. 2013 г.
*/
public class VeryDifficultOperationSpringStopWatch
{
/**
* Точка входа в операцию
*/
public void execute()
{
StopWatch sw = createStopWatch("VeryDifficultOperation");
sw.start("Step1");
System.out.println(sw.shortSummary());
step1();
sw.stop();
sw.start("Step2");
System.out.println(sw.shortSummary());
step2();
sw.stop();
compositeStep3(sw);
System.out.println(sw.prettyPrint());
}
/**
* Шаг 1
*/
private void step1()
{
waitRandomDelay();
}
/**
* Шаг 2
*/
private void step2()
{
waitRandomDelay();
}
/**
* Сложный составной шаг 3
*/
private void compositeStep3(StopWatch sw)
{
sw.start("Step31");
System.out.println(sw.shortSummary());
step31();
sw.stop();
sw.start("Step32");
System.out.println(sw.shortSummary());
step32();
sw.stop();
sw.start("Step33");
System.out.println(sw.shortSummary());
step33();
sw.stop();
}
/**
* Первая часть шага 3
*/
private void step31()
{
waitRandomDelay();
}
/**
* Вторая часть шага 3
*/
private void step32()
{
waitRandomDelay();
}
/**
* Первая часть шага 3
*/
private void step33()
{
waitRandomDelay();
}
private void waitRandomDelay()
{
Random rmd = new Random();
int randomDelay = rmd.nextInt(3000);
try
{
Thread.sleep(randomDelay);
}
catch (InterruptedException e)
{
e.printStackTrace();
System.exit(1);
}
}
private StopWatch createStopWatch(String id)
{
return new StopWatch(id)
{
@Override
public String shortSummary()
{
try
{
return super.shortSummary() + " LastTask: " + getLastTaskName() + " completed for "
+ getLastTaskTimeMillis() + "ms";
}
catch (IllegalStateException e)
{
return super.shortSummary();
}
}
};
}
public static void main(String[] args)
{
VeryDifficultOperationSpringStopWatch operation = new VeryDifficultOperationSpringStopWatch();
operation.execute();
}
}
Я доопределил метод shortSummary() добавив туда информацию о выполнении последней задачи, чтобы можно было логировать процесс выполнения операций.
StopWatch 'VeryDifficultOperation': running time (millis) = 0
StopWatch 'VeryDifficultOperation': running time (millis) = 2886 LastTask: Step1 completed for 2886ms
StopWatch 'VeryDifficultOperation': running time (millis) = 2968 LastTask: Step2 completed for 82ms
StopWatch 'VeryDifficultOperation': running time (millis) = 3933 LastTask: Step31 completed for 965ms
StopWatch 'VeryDifficultOperation': running time (millis) = 5028 LastTask: Step32 completed for 1095ms
StopWatch 'VeryDifficultOperation': running time (millis) = 6636 LastTask: Step33 completed for 1608ms
-----------------------------------------
ms % Task name
-----------------------------------------
02886 043% Step1
00082 001% Step2
00965 015% Step31
01095 017% Step32
01608 024% Step33
Таким образом, получили достаточно лаконичный код и красивый вывод в консоль информации практически из коробки. Думаю, что для решения моей задачи Spring StopWatch подошел бы лучше всего. Жаль что его не было в проекте.
Выводы
Кратко охарактеризую каждый из рассмотренных секундомеров:- GUAVA Stopwatch - быстрый, простой, точный.
- Apache Commons Lang Stopwatch - простой, немного нелогичный.
- Spring StopWatch - многоэтапный, с хорошим выводом состояний.
Спасибо за внимание, жду комментариев!
