Почему время запросов в журнале Google App Engine отличается от времени в Appstats?

Я запускаю Appstats в своем Java-приложении HDR в Google. App Engine. Прямо сейчас я несколько озадачен различиями в значениях времени между фактическим журналом запросов App Engine и журналами Appstats. Похоже, что между этими временами существует значительный дрейф. Чтобы объяснить, что я имею в виду, я привел несколько скриншотов. Оба они из одного запроса.

Это из журнала запросов App Engine:

Журнал запросов App Engine

И это для того же запроса от Appstats:

Хронология статистики приложений

Вот список измерений, которые мне удалось извлечь:

Log Timestamp           10:10:33.156
Log "Total"                    147ms
Log "ms"                       147ms
Log "cpu_ms"                    86ms

Appstats Timestamp      10:10:33.072
Appstats "Grand Total"          39ms
Appstats "real"                 39ms
Appstats "RPC Total"            20ms
Appstats "api"                   0ms
Appstats "overhead"              0ms

Как видите, существует большая разница как во временной метке запроса, так и во времени выполнения:

Difference Log/AS Timestamps    84ms
Difference Log/AS Total        108ms (377%)

Между прочим: хотя временные метки запроса не совпадают, это все равно тот же запрос: я перешел по ссылке Appstats, опубликованной в журнале запросов, и выполнил этот тест в другом неиспользуемом тестовом приложении, чтобы я мог убедиться, что ссылка верна .

Почему Appstats сообщает мне, что мой запрос занял 39 мс, в то время как журнал запросов GAE сообщает мне, что запрос длился в 3,8 раза (147 мс)? Почему у одного и того же запроса две разные отметки времени?

Большое спасибо!


google-app-engine appstats
person Holger    schedule 10.02.2014    source источник

Ответы (1)


arrow_upward
0
arrow_downward

appstats привязан к вашему коду, пройдет некоторое время до того, как ваш код (appstats) будет вызван, а также после выхода из appstats. Помните, что appengine не передает поток к клиенту, но весь вывод передается в какой-то буфер, а затем передается в инфраструктуру appengine для доставки.

Временная шкала запроса будет примерно такой:

  1. начало запроса (время начала вы видите в логах)
  2. запуск кода, покрытого appstats
  3. конец кода, покрытого appstats
  4. окончательный ответ отправлен (общая продолжительность)

Было бы интересно посмотреть, сколько в среднем будет 1 и 4, и это может зависеть от времени выполнения.

Да, и у самой appstats будут некоторые накладные расходы, которые не будут измеряться appstats, включая запуск и очистку в конце, которые влияют на время в 1 и 2.

person Tim Hoffman    schedule 10.02.2014
comment
Привет, Тим! Спасибо, что ответили так быстро. Я понимаю, что до того, как Appstats сможет сработать, будут накладные расходы на каждый запрос. Забавно то, что временная метка Appstats находится перед временной меткой журнала запроса, что говорит о том, что временная метка журнала не является началом запроса? - person Holger; 10.02.2014
comment
В качестве альтернативы, время начала запроса в системах регистрации не по тем же часам, а обеспечивается внешней инфраструктурой - просто предположение. - person Tim Hoffman; 10.02.2014
comment
На самом деле, если вы думаете об этом, записи журнала поступают из службы журнала, а временные метки будут из службы журнала. Часы службы журнала могут отличаться от часов вашего экземпляра (часы экземпляров могут немного отличаться друг от друга). Чтобы проверить эту теорию, запишите созданную вами метку времени и посмотрите, совпадает ли она с меткой времени записей журнала. - person Tim Hoffman; 11.02.2014