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

Определение места подвисания запросов (Profiling & Debugging)

Это один из самых практических навыков. За 10+ лет я использовал разные техники для поиска bottleneck-ов.

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

Самый простой первый шаг:

@Service
public class OrderService {
  private static final Logger logger = LoggerFactory.getLogger(OrderService.class);
  
  public void processOrder(Order order) {
    long start = System.currentTimeMillis();
    logger.info("[START] Processing order {}", order.getId());
    
    long beforeDB = System.currentTimeMillis();
    orderRepository.save(order);
    long dbDuration = System.currentTimeMillis() - beforeDB;
    logger.info("[DB] Saved order, duration: {}ms", dbDuration);
    
    long beforePayment = System.currentTimeMillis();
    paymentService.process(order);
    long paymentDuration = System.currentTimeMillis() - beforePayment;
    logger.info("[PAYMENT] Processed payment, duration: {}ms", paymentDuration);
    
    long beforeNotify = System.currentTimeMillis();
    notificationService.notify(order);
    long notifyDuration = System.currentTimeMillis() - beforeNotify;
    logger.info("[NOTIFY] Sent notification, duration: {}ms", notifyDuration);
    
    long totalDuration = System.currentTimeMillis() - start;
    logger.info("[TOTAL] Order processing completed in {}ms", totalDuration);
  }
}

Вывод в логах:

[START] Processing order 123
[DB] Saved order, duration: 45ms
[PAYMENT] Processed payment, duration: 2345ms  <- ЗДЕСЬ подвис!
[NOTIFY] Sent notification, duration: 12ms
[TOTAL] Order processing completed in 2402ms

2. Spring Boot Actuator (для metrics)

В production используем метрики:

<dependency>
  <groupId>org.springframework.boot</groupId>
  <artifactId>spring-boot-starter-actuator</artifactId>
</dependency>
<dependency>
  <groupId>io.micrometer</groupId>
  <artifactId>micrometer-registry-prometheus</artifactId>
</dependency>

@Service
public class OrderService {
  
  private final MeterRegistry meterRegistry;
  
  @Transactional
  public void processOrder(Order order) {
    Timer.Sample sample = Timer.start(meterRegistry);
    
    try {
      // Работа
      orderRepository.save(order);
      paymentService.process(order);
      notificationService.notify(order);
    } finally {
      sample.stop(Timer.builder("order.processing")
        .description("Order processing time")
        .tag("status", "success")
        .register(meterRegistry));
    }
  }
}

// Или через @Timed аннотацию
@Timed(value = "order.processing", description = "Time to process order")
public void processOrder(Order order) {
  // Автоматически измеряется
}

Эндпоинт для метрик:

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

Ответ:
{
  "name": "order.processing",
  "description": "Time to process order",
  "baseUnit": "seconds",
  "measurements": [
    {"statistic": "COUNT", "value": 1234},
    {"statistic": "TOTAL", "value": 2345.67},
    {"statistic": "MAX", "value": 5.23}
  ]
}

3. JProfiler и YourKit (профилеры)

Для глубокого анализа потоков и памяти:

# Запустить приложение с профилером
java -agentpath:/path/to/jprofiler/bin/linux-x64/libjprofilerti.so=port=8849 -jar app.jar

Что видим:

• Какие методы занимают больше всего времени
• Какие потоки заблокированы
• Утечки памяти
• CPU профайл

4. Thread Dump (потоки в production)

Если приложение зависло — берём thread dump:

# Найти PID Java процесса
jps -l

# Получить thread dump
jstack <PID> > thread_dump.txt

Анализируем:

// thread_dump.txt содержит:
"pool-1-thread-1" prio=10 tid=0x00007f8b8d0d9000 nid=0x38a4 
  waiting for monitor entry [0x00007f8b8a2fc000]
  java.lang.Object.wait(Native Method)
  java.lang.Object.wait(Object.java:485)
  com.example.OrderService.processPayment(OrderService.java:45) <- ЗДЕСЬ!
  - waiting to lock <0x00000000c18f0f20> (a java.lang.Object)
    at com.example.PaymentGateway.process(PaymentGateway.java:100)

Онлайн анализ: http://fastthread.io/ (загрузить dump)

5. Database Query Profiling

Если БД медленная:

@Configuration
public class JpaConfig {
  @Bean
  public PersistenceUnitPostProcessor persistenceUnitPostProcessor() {
    return pui -> {
      // Логирование SQL запросов
      Map<String, Object> properties = pui.getProperties();
      properties.put("hibernate.generate_statistics", true);
      properties.put("hibernate.use_sql_comments", true);
    };
  }
}

// В application.yml
spring:
  jpa:
    properties:
      hibernate:
        generate_statistics: true
        format_sql: true
logging:
  level:
    org.hibernate.stat: DEBUG
    org.hibernate.SQL: DEBUG
    org.hibernate.type.descriptor.sql.BasicBinder: TRACE

В логах увидим:

Hibernate: SELECT id, name FROM users WHERE id = ?
  - Binding: [123]
  - Time: 456ms  <- ДОЛГО!

Используем EXPLAIN PLAN:

EXPLAIN ANALYZE
SELECT * FROM orders
WHERE customer_id = $1
ORDER BY created_at DESC
LIMIT 10;

-- Видим индексы и план выполнения
Seq Scan on orders (cost=0.00..5000.00 rows=100000)  <- ОЧЕНЬ МЕДЛЕННО
  Filter: (customer_id = $1)

-- Нужен индекс!
CREATE INDEX idx_orders_customer_id ON orders(customer_id);

6. Async Profiler (самый современный)

JDK 11+, встроенный профилер:

# Скачать async-profiler
wget https://github.com/async-profiler/async-profiler/releases/download/v3.0/async-profiler-3.0-linux-x64.tar.gz
tar xzf async-profiler-3.0-linux-x64.tar.gz

# Запустить профилирование
./profiler.sh -d 30 -f /tmp/profile.html <PID>

# Откроем HTML в браузере - видим flame graph

7. Spring Cloud Sleuth + Distributed Tracing

Для микросервисных архитектур:

<dependency>
  <groupId>org.springframework.cloud</groupId>
  <artifactId>spring-cloud-starter-sleuth</artifactId>
</dependency>
<dependency>
  <groupId>org.springframework.cloud</groupId>
  <artifactId>spring-cloud-sleuth-zipkin</artifactId>
</dependency>

spring:
  zipkin:
    base-url: http://localhost:9411
  sleuth:
    sampler:
      probability: 1.0  # Трейсим 100% запросов

Автоматически видим:

• Какие микросервисы вызываются
• Время на каждый вызов
• Зависимость вызовов

8. Checklist для поиска подвисания

// 1️⃣ Логирование (быстро)
logger.info("[STEP_1] Processing started");
// ... работа
logger.info("[STEP_1] Processing finished");

// 2️⃣ Metrics (production)
@Timed(value = "my.operation")
public void operation() { ... }

// 3️⃣ Database (если работаем с БД)
// Включить hibernate statistics
// Смотреть slow query log

// 4️⃣ External calls (API вызовы)
// Добавить timeout
RestTemplate template = new RestTemplate();
template.setRequestFactory(new HttpComponentsClientHttpRequestFactory() {
  {
    getHttpClient().setConnectionManager(...);
  }
});

// 5️⃣ Thread dump (если зависло)
jstack <PID> > dump.txt

// 6️⃣ Profiler (для детального анализа)
// async-profiler или YourKit

Практический пример: Найти подвис

@RestController
public class OrderController {
  
  private static final Logger logger = LoggerFactory.getLogger(OrderController.class);
  
  @PostMapping("/orders")
  public OrderResponse createOrder(@RequestBody CreateOrderRequest request) {
    long start = System.currentTimeMillis();
    logger.info("[1] Request received");
    
    // Валидация
    long step = System.currentTimeMillis();
    validateOrder(request);
    logger.info("[2] Validation: {}ms", System.currentTimeMillis() - step);
    
    // Сохранение
    step = System.currentTimeMillis();
    Order order = orderService.createOrder(request);
    logger.info("[3] Save to DB: {}ms", System.currentTimeMillis() - step);
    
    // Платёж
    step = System.currentTimeMillis();
    paymentService.process(order);
    logger.info("[4] Payment: {}ms", System.currentTimeMillis() - step);
    
    // Ответ
    step = System.currentTimeMillis();
    OrderResponse response = OrderMapper.toResponse(order);
    logger.info("[5] Mapping: {}ms", System.currentTimeMillis() - step);
    
    logger.info("[TOTAL] Request processed in {}ms", System.currentTimeMillis() - start);
    return response;
  }
}

// Логи покажут:
// [1] Request received
// [2] Validation: 5ms
// [3] Save to DB: 50ms
// [4] Payment: 15000ms  <- ЗДЕСЬ ПОДВИС!
// [5] Mapping: 2ms
// [TOTAL] Request processed in 15057ms

Итоговая стратегия

Этап 1 (быстро): Логирование с временными метками Этап 2: Spring Actuator metrics Этап 3: Database EXPLAIN PLAN Этап 4 (если нужно): Async Profiler Этап 5: Thread dump анализ

В 90% случаев логирование найдёт проблему в 5 минут.