Spring, JPA web application - проблема с измерением времени обработки

Question

Я пытаюсь измерить и оптимизировать время отклика в моем веб-приложении, но у меня странные результаты, которых я не понимаю. У меня есть метод контроллера, который вызывает службу, которая получает документ из БД. Услуга состоит из 3-х потенциальных звонков в БД:

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

Вот код услуги:

    @Override
    @Transactional(readOnly = true)
    public DocumentFile getDocumentContentWithPerformanceMeasurement(Long entryId, Statistic stat) {
        StopWatch methodWatch = new StopWatch();
        methodWatch.start();
        stat.setServiceThreadName(Thread.currentThread().getName());

        StopWatch watch = new StopWatch();
        watch.start();
        Entry entry = dao.getDocumentWithContent(entryId);

        watch.stop();
        stat.getActions().add(new ActionStat(MonitoringAction.DOCUMENT_OBJECT_RETRIEVED, watch.getTime()));
        watch.reset();

        watch.start();
        permissionService.checkPermission(entry.getOwner(), Action.VIEW);
        watch.stop();
        stat.getActions().add(new ActionStat(MonitoringAction.PERMISSION_CHECK, watch.getTime()));
        watch.reset();

        watch.start();
        DocumentFile file = new DocumentFile(entry.getName(), entry.getSignature().getContent());
        watch.stop();
        stat.getActions().add(new ActionStat(MonitoringAction.DOCUMENT_SIGNATURE_RETRIEVED, watch.getTime()));
        watch.reset();

        methodWatch.stop();
        stat.getActions().add(new ActionStat(MonitoringAction.SERVICE_METHOD_COMPLETED, methodWatch.getTime()));

        return file;
    }

Каждый шаг измеряется с помощью commons.lang3 StopWatch. Теперь в методе контроллера я также измеряю весь вызов метода сервиса. Вот фрагмент кода:

    StopWatch watch = new StopWatch();
    watch.start();
    DocumentFile entry = entryService.getDocumentContentWithPerformanceMeasurement(documentId, stat);
    watch.stop();
    stat.getActions().add(new ActionStat(MonitoringAction.CONTROLLER_DOCUMENT_RETRIEVED, watch.getTime()));

А теперь результаты. БД требует объект документа и разрешение длилось 15 мс. Выборка подписи документа длилась 0 мс, и это нормально, так как отношение не ленивое, а подпись уже была извлечена при вызове объекта документа. Весь метод обслуживания завершен за 15 мс, но контроллер ждал 158 мс для результата. Зачем? Это из-за @Transactional? Я должен использовать транзакционный, поскольку я использую PostgreSQL, содержимое файла хранится в виде oid в нескольких таблицах.

    http-nio-9090-exec-4, http-nio-9090-exec-4 - 
    DOCUMENT_OBJECT_RETRIEVED (10ms), 
    PERMISSION_CHECK (5ms), 
    DOCUMENT_SIGNATURE_RETRIEVED (0ms), 
    SERVICE_METHOD_COMPLETED (15ms), 
    CONTROLLER_DOCUMENT_RETRIEVED (158ms), 
    PRINT_CONTENT (0ms), 
    REQUEST_COMPLETED (159ms)