Я использую GAE / Java. Я записываю время выполнения моего кода
внутри кода и вывести его в журналы как отладочное сообщение. Время это
выполнение моего кода обычно занимает лишь часть времени, которое
отображается в журналах как общее время ответа на запрос.
Например, в моем коде мое отладочное сообщение скажет, что мой код занял 58мс
запустить. Но строка журнала покажет: / 421ms 130cpu_ms 20api_cpu_ms,
показывая, что для возврата ответа потребовалось 421 мс.
Это типично для
каждый запрос, это не связано с загрузкой запросов. Кроме того, я единственный
человек, обращающийся к моему приложению прямо сейчас, и журналы не отображают значение pending_ms, так что это не потому, что он ожидает, пока другой запрос завершит обработку первым.
Что вызывает эту дополнительную задержку? Есть ли способ, как я могу это исправить?
EDIT:
Я создал новый проект движка приложений с нуля, чтобы понять, не проблема ли это с моим приложением или что-то происходит с движком приложения. В новом проекте есть один сервлет, который отображается на /*, а код этого сервлета:
protected void doGet(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException {
long time = System.nanoTime();
long x = 5;
for (int i = 0; i < 1234567; i++) { x += i % 3 == 0 ? -i : i; }
response.getWriter().write(request.getRequestURI().toLowerCase() + x);
log.fine(getTime(time, "Total Time"));
}
static String getTime(long origtime, String id) {
long diff = System.nanoTime() - origtime;
long ret = diff / 100000;
return id + ": " + ((double)ret / 10) + " ms";
}
РЕЗУЛЬТАТЫ: Даже с этим очень простым проектом движка приложения, я вижу то же самое поведение. Будет вывод журнала, например Total Time: 7.8 ms, но строка журнала покажет, что задержка значительно выше, чем 159ms 23cpu_ms. Это не всегда так плохо, иногда в строке журнала отображается задержка всего около 40 мс, а в отладочном сообщении время составляет около 7 мс.