Как определить место, на которое затрачивается лишнее время в SLA?

# Как определить место, на которое затрачивается лишнее время в SLA

Это вопрос о профилировании и мониторинге приложений. SLA (Service Level Agreement) требует выполнения операций за определённое время. Вот способы найти узкие места.

1. Логирование с временем выполнения (простой способ)

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

@Service
public class UserService {
    private static final Logger logger = LoggerFactory.getLogger(UserService.class);
    
    public User getUser(Long id) {
        long start = System.currentTimeMillis();
        logger.info("Начало getUser для id={}", id);
        
        try {
            // Поиск в БД
            User user = userRepository.findById(id).orElse(null);
            long dbTime = System.currentTimeMillis() - start;
            logger.info("БД запрос занял {}ms", dbTime);
            
            // Дополнительная обработка
            user.setRoles(roleService.getUserRoles(id));
            long rolesTime = System.currentTimeMillis() - start - dbTime;
            logger.info("Получение ролей заняло {}ms", rolesTime);
            
            long totalTime = System.currentTimeMillis() - start;
            logger.info("getUser завершён за {}ms (SLA: 100ms)", totalTime);
            
            return user;
        } catch (Exception e) {
            logger.error("Ошибка в getUser", e);
            throw new RuntimeException(e);
        }
    }
}

2. AOP для профилирования (декларативный способ)

// Aspect для логирования времени выполнения
@Aspect
@Component
public class PerformanceMonitoringAspect {
    private static final Logger logger = LoggerFactory.getLogger(PerformanceMonitoringAspect.class);
    
    @Around("@annotation(monitored)")
    public Object monitorPerformance(ProceedingJoinPoint joinPoint, Monitored monitored) throws Throwable {
        String methodName = joinPoint.getSignature().getName();
        long slaMs = monitored.slaMs();
        
        long start = System.currentTimeMillis();
        try {
            Object result = joinPoint.proceed();
            long duration = System.currentTimeMillis() - start;
            
            if (duration > slaMs) {
                logger.warn("SLA нарушена для {}: {}ms > {}ms", methodName, duration, slaMs);
            } else {
                logger.info("{} выполнен за {}ms (SLA: {}ms)", methodName, duration, slaMs);
            }
            return result;
        } catch (Exception e) {
            long duration = System.currentTimeMillis() - start;
            logger.error("{} упал после {}ms с ошибкой", methodName, duration, e);
            throw e;
        }
    }
}

// Аннотация
@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
public @interface Monitored {
    long slaMs() default 100;  // 100ms по умолчанию
}

// Использование
@Service
public class UserService {
    @Monitored(slaMs = 100)
    public User getUser(Long id) {
        // реализация
    }
}

3. Использование Micrometer + Prometheus

@Service
public class UserService {
    private final MeterRegistry meterRegistry;
    
    public UserService(MeterRegistry meterRegistry) {
        this.meterRegistry = meterRegistry;
    }
    
    public User getUser(Long id) {
        return meterRegistry.timer(
            "user.get.duration",
            "operation", "database"
        ).recordCallable(() -> {
            // Код для получения пользователя
            return userRepository.findById(id).orElse(null);
        });
    }
}

// В application.yml
spring:
  application.name: user-service
management:
  endpoints.web.exposure.include: prometheus
  metrics:
    export.prometheus.enabled: true

Далее вы можете запросить метрики:

curl http://localhost:8080/actuator/prometheus | grep user_get

4. Профилировщик JProfiler / YourKit

Для детального анализа можно использовать профилировщики:

// Запуск с профилировщиком
java -agentpath:/path/to/yjpagent.so=sampling app.jar

// Или с JProfiler
java -agentpath:/path/to/jprofiler/bin/linux-x64/libjprofilerti.so app.jar

Профилировщик покажет:

• Которая функция занимает больше всего времени
• Сколько раз она вызывается
• Средний/максимальный/минимальный виремя

5. Tracing с Jaeger/Zipkin

Для распределённых систем:

// Добавьте зависимость
// <dependency>
//     <groupId>io.opentelemetry.instrumentation</groupId>
//     <artifactId>opentelemetry-spring-boot-starter</artifactId>
// </dependency>

@Service
public class UserService {
    private final Tracer tracer;
    
    public UserService(Tracer tracer) {
        this.tracer = tracer;
    }
    
    public User getUser(Long id) {
        Span span = tracer.spanBuilder("getUserFromDatabase")
            .setAttribute("user.id", id)
            .startSpan();
        
        try (Scope scope = span.makeCurrent()) {
            User user = userRepository.findById(id).orElse(null);
            span.setStatus(StatusCode.OK);
            return user;
        } catch (Exception e) {
            span.setStatus(StatusCode.ERROR);
            span.recordException(e);
            throw e;
        } finally {
            span.end();
        }
    }
}

6. Рекурсивное профилирование

Большой запрос часто состоит из нескольких операций. Найдите узкое место:

@Service
public class OrderService {
    private final OrderRepository orderRepository;
    private final UserService userService;
    private final PaymentService paymentService;
    private final StockService stockService;
    
    @Monitored(slaMs = 500)  // Общее SLA: 500ms
    public Order createOrder(OrderRequest request) {
        // 1. Проверка пользователя
        User user = userService.getUser(request.getUserId());  // ~50ms
        
        // 2. Резервирование товара
        Stock stock = stockService.reserveItem(request.getItemId());  // ~100ms
        
        // 3. Обработка платежа
        Payment payment = paymentService.charge(request.getAmount());  // ~300ms (узкое место!)
        
        // 4. Сохранение заказа
        Order order = new Order(user, stock, payment);
        return orderRepository.save(order);  // ~30ms
    }
}

// Результат:
// 50ms + 100ms + 300ms + 30ms = 480ms (OK)
// Но если paymentService упадёт до 600ms, нарушится SLA

7. Техника "Binary Search" для профилирования

@Service
public class SearchService {
    
    public List<Product> search(String query) {
        long start = System.currentTimeMillis();
        
        // Шаг 1: Поиск в индексе
        List<Long> ids = searchIndex(query);  // т.н. "первая половина"
        long afterSearch = System.currentTimeMillis();
        System.out.println("Search: " + (afterSearch - start));
        
        // Шаг 2: Загрузка из БД
        List<Product> products = loadFromDatabase(ids);  // "вторая половина"
        long afterLoad = System.currentTimeMillis();
        System.out.println("Load: " + (afterLoad - afterSearch));
        
        // Шаг 3: Обогащение данных
        List<Product> enriched = enrichProducts(products);
        long afterEnrich = System.currentTimeMillis();
        System.out.println("Enrich: " + (afterEnrich - afterLoad));
        
        long total = System.currentTimeMillis() - start;
        System.out.println("Total: " + total);
        
        return enriched;
    }
}

// Вывод:
// Search: 5ms
// Load: 80ms
// Enrich: 200ms (узкое место!)
// Total: 285ms

8. SQL Slow Log

Частая причина нарушения SLA — медленные SQL запросы:

# application.yml
spring:
  jpa:
    properties:
      hibernate:
        session.events.log: true
        generate_statistics: true

logging:
  level:
    org.hibernate.stat: DEBUG
    org.hibernate.SQL: DEBUG
    org.hibernate.type.descriptor.sql.BasicBinder: TRACE

Кроме того, в PostgreSQL:

ALTER SYSTEM SET log_min_duration_statement = 100;  -- Логировать запросы > 100ms
SELECT pg_reload_conf();

SELECT query, calls, mean_time, max_time
FROM pg_stat_statements
ORDER BY mean_time DESC
LIMIT 10;

9. Кэширование для быстрых SLA

@Service
public class UserService {
    private final UserRepository repository;
    private final Cache<Long, User> cache = new LoadingCache<>();
    
    @Monitored(slaMs = 50)  // Жесткое SLA!
    public User getUser(Long id) {
        // Сначала проверяем кэш
        User cached = cache.getIfPresent(id);
        if (cached != null) {
            return cached;  // ~1ms из кэша
        }
        
        // Если нет в кэше, загружаем из БД
        User user = repository.findById(id).orElse(null);
        if (user != null) {
            cache.put(id, user);  // Кэшируем
        }
        return user;  // ~100ms из БД
    }
}

Алгоритм поиска узких мест

1. Включите логирование с временем для каждого шага
2. Определите SLA для каждого метода
3. Запустите нагрузочный тест и посмотрите логи
4. Выпишите времена всех операций
5. Отсортируйте по времени (найти максимум)
6. Оптимизируйте максимальную операцию
7. Повторите пока не достигнете SLA

Вывод

Для определения узких мест в SLA используйте:

• Логирование для быстрого анализа
• Metrics/Prometheus для постоянного мониторинга
• Tracing для распределённых систем
• Профилировщики для детального анализа
• Binary search для ускорения поиска
• Кэширование для быстрых SLA