Как найти проблемные места при медленной работе приложения

Поиск проблемных мест при медленной работе приложения

Это одна из самых важных задач разработчика — найти и устранить узкие места (bottlenecks). Рассмотрю систематический подход и инструменты для профилирования.

1. Логирование времени выполнения операций

Самый простой и часто самый эффективный подход:

@Service
public class OrderService {
    private static final Logger log = LoggerFactory.getLogger(OrderService.class);
    
    public Order processOrder(Long orderId) {
        long startTime = System.currentTimeMillis();
        try {
            // Логируем промежуточные операции
            log.info("Starting order processing for orderId={}", orderId);
            
            long dbStart = System.currentTimeMillis();
            Order order = orderRepository.findById(orderId);
            log.info("Database query took {}ms", System.currentTimeMillis() - dbStart);
            
            long processStart = System.currentTimeMillis();
            order.process();
            log.info("Business logic took {}ms", System.currentTimeMillis() - processStart);
            
            return order;
        } finally {
            log.info("Total order processing took {}ms", 
                System.currentTimeMillis() - startTime);
        }
    }
}

2. Spring AOP для автоматического профилирования

Аспект, который логирует время выполнения всех методов в сервисе:

@Aspect
@Component
@Slf4j
public class PerformanceAspect {
    
    @Around("execution(* com.example.service..*.*(..))")
    public Object measureExecutionTime(ProceedingJoinPoint joinPoint) throws Throwable {
        long startTime = System.currentTimeMillis();
        
        Object result = joinPoint.proceed();
        
        long duration = System.currentTimeMillis() - startTime;
        
        String methodName = joinPoint.getSignature().getName();
        String className = joinPoint.getTarget().getClass().getSimpleName();
        
        if (duration > 500) { // Логируем если больше 500ms
            log.warn("SLOW METHOD: {}.{}() took {}ms", 
                className, methodName, duration);
        } else {
            log.debug("{}.{}() took {}ms", className, methodName, duration);
        }
        
        return result;
    }
}

3. Использование микро-метрик

Отслеживание операций на более детальном уровне:

public class PerformanceTimer implements AutoCloseable {
    private final long startTime;
    private final String operation;
    
    public PerformanceTimer(String operation) {
        this.operation = operation;
        this.startTime = System.nanoTime();
    }
    
    @Override
    public void close() {
        long duration = (System.nanoTime() - startTime) / 1_000_000; // в ms
        if (duration > 100) {
            System.out.println(operation + " took " + duration + "ms");
        }
    }
}

// Использование
public List<User> getAllUsers() {
    try (PerformanceTimer timer = new PerformanceTimer("getAllUsers")) {
        return userRepository.findAll();
    }
}

4. Анализ потребления памяти

Ограничение памяти для JVM и мониторинг:

# Запуск приложения с ограничением памяти
java -Xms256m -Xmx1024m -XX:+PrintGCDetails -XX:+PrintGCDateStamps \
     -Xloggc:gc.log -jar application.jar

Анализ GC логов:

// Мониторинг памяти в коде
public void checkMemoryUsage() {
    Runtime runtime = Runtime.getRuntime();
    long maxMemory = runtime.maxMemory();
    long totalMemory = runtime.totalMemory();
    long freeMemory = runtime.freeMemory();
    long usedMemory = totalMemory - freeMemory;
    
    double percentUsed = (double) usedMemory / maxMemory * 100;
    
    if (percentUsed > 80) {
        log.warn("Memory usage is high: {}%", percentUsed);
    }
}

5. Использование JProfiler или YourKit

Профессиональные инструменты для профилирования:

# Запуск с подключением профайлера
java -agentpath:/path/to/yjpagent.so -jar application.jar

В коде можно отмечать точки профилирования:

import com.yourkit.api.Controller;

public class ProfiledService {
    public void importantOperation() {
        Controller.startCPUProfiling();
        
        try {
            // Выполняем операцию
            doWork();
        } finally {
            byte[] snapshot = Controller.captureSnapshot(
                Controller.SNAPSHOT_WITH_HEAP
            );
            Controller.stopCPUProfiling();
        }
    }
}

6. Spring Boot Actuator для мониторинга

Включение в pom.xml:

<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-actuator</artifactId>
</dependency>

Конфигурация в application.properties:

management.endpoints.web.exposure.include=metrics,health,env
management.endpoint.health.show-details=always
management.endpoint.metrics.enabled=true

Кастомные метрики:

@Service
public class OrderService {
    @Autowired
    private MeterRegistry meterRegistry;
    
    public Order processOrder(Long id) {
        long startTime = System.currentTimeMillis();
        Order order = orderRepository.findById(id);
        
        long duration = System.currentTimeMillis() - startTime;
        meterRegistry.timer("order.processing").record(duration, TimeUnit.MILLISECONDS);
        
        return order;
    }
}

Проверка метрик:

curl http://localhost:8080/actuator/metrics
curl http://localhost:8080/actuator/metrics/order.processing

7. Анализ потоков (Thread Dump)

При зависании приложения снимите thread dump:

#找到процесс
jps -l

# Снять thread dump
jstack <pid> > threadDump.txt

# Или через jcmd
jcmd <pid> Thread.print > threadDump.txt

Анализируем в коде:

public void analyzeThreads() {
    ThreadMXBean threadBean = ManagementFactory.getThreadMXBean();
    
    long[] threadIds = threadBean.getAllThreadIds();
    System.out.println("Total threads: " + threadIds.length);
    
    for (long threadId : threadIds) {
        ThreadInfo info = threadBean.getThreadInfo(threadId);
        if (info.getThreadState() == Thread.State.BLOCKED) {
            System.out.println("BLOCKED: " + info.getThreadName());
        }
    }
}

8. Анализ CPU с помощью async-profiler

# Компилирование async-profiler
git clone https://github.com/async-profiler/async-profiler.git
cd async-profiler && make

# Запуск профилирования
./profiler.sh -d 30 -f /tmp/flame.html <pid>

9. Использование StopWatch для измерения

Spring утилита для простого измерения:

import org.springframework.util.StopWatch;

public void processData() {
    StopWatch stopWatch = new StopWatch("dataProcessing");
    
    stopWatch.start("loadData");
    List<Data> data = loadData();
    stopWatch.stop();
    
    stopWatch.start("transformData");
    List<Data> transformed = transformData(data);
    stopWatch.stop();
    
    stopWatch.start("saveData");
    saveData(transformed);
    stopWatch.stop();
    
    System.out.println(stopWatch.prettyPrint());
}

10. Hibernate Query Profiling

Для анализа запросов к БД:

spring.jpa.properties.hibernate.generate_statistics=true
spring.jpa.properties.hibernate.use_sql_comments=true
spring.jpa.properties.hibernate.format_sql=true
logging.level.org.hibernate.stat=DEBUG
logging.level.org.hibernate.SQL=DEBUG
logging.level.org.hibernate.type.descriptor.sql.BasicBinder=TRACE

@Service
public class UserService {
    @PersistenceContext
    private EntityManager em;
    
    public void analyzeQueries() {
        SessionFactory factory = em.getEntityManagerFactory()
            .unwrap(SessionFactory.class);
        Statistics stats = factory.getStatistics();
        
        System.out.println("Total queries: " + stats.getQueryExecutionCount());
        System.out.println("Slow query threshold: 10ms");
        
        for (String query : stats.getQueries()) {
            QueryStatistics qs = stats.getQueryStatistics(query);
            if (qs.getExecutionAvgTime() > 10) {
                System.out.println("SLOW: " + query + 
                    " avg=" + qs.getExecutionAvgTime() + "ms");
            }
        }
    }
}

11. Практический пример: поиск N+1 проблемы

// ПЛОХО: N+1 запросы
@Repository
public class UserRepository extends JpaRepository<User, Long> {
    // Без eager loading
    @Override
    List<User> findAll();
}

// Код, который вызывает N+1
List<User> users = userRepository.findAll(); // 1 запрос
for (User user : users) {
    List<Order> orders = user.getOrders(); // N запросов!
}

// РЕШЕНИЕ 1: Eager loading
@Entity
public class User {
    @OneToMany(fetch = FetchType.EAGER)
    private List<Order> orders;
}

// РЕШЕНИЕ 2: Использование join fetch
@Repository
public interface UserRepository extends JpaRepository<User, Long> {
    @Query("SELECT DISTINCT u FROM User u LEFT JOIN FETCH u.orders")
    List<User> findAllWithOrders();
}

// РЕШЕНИЕ 3: Batch loading
@Entity
public class User {
    @OneToMany(fetch = FetchType.LAZY)
    @Fetch(FetchMode.BATCH)
    @BatchSize(size = 10)
    private List<Order> orders;
}

Пошаговый алгоритм поиска проблемных мест

1. Определите симптом — медленнее запросы, утечка памяти, high CPU?
2. Логируйте время — добавьте логирование вокруг подозрительного кода
3. Используйте Actuator — проверьте метрики в production
4. Анализируйте GC — включите логирование GC
5. Снимите thread dump — если есть зависания
6. Используйте профайлер — для детального анализа
7. Проверьте БД — используйте EXPLAIN ANALYZE
8. Оптимизируйте — устраните обнаруженные проблемы
9. Тестируйте — убедитесь, что оптимизация работает
10. Мониторьте — продолжайте следить в production

Лучшие практики

1. Логируйте рано, часто и стратегически — не переполняйте логи
2. Используйте аспекты для кроссекспектирующих забот — не дублируйте код
3. Устанавливайте пороги для алертов — реагируйте на проблемы быстро
4. Профилируйте в production подобной окружении — dev режим может скрывать проблемы
5. Документируйте найденные проблемы — помогает избежать регрессий

Профилирование — это постоянный процесс поддержания производительности приложения.