Google App Engine - информация о трассировке скрытой консоли Stackdriver

Question

Я пытаюсь лучше понять, как трассировка Stackdriver в Google Cloud Console показывает детали вызовов и отлаживает некоторые проблемы с производительностью для моего приложения. Большинство запросов работают в основном с помощью набора memcache/get, и у меня возникают некоторые проблемы, но я не понимаю, почему существует много времени между вызовами. Я загрузил 2 скриншота.

Итак, как вы можете видеть, вызов @ 1025ms взял 2ms, но есть больше, чем 4 секунды между ним и UrlFetch вызова @ 5235ms.

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

Обратите внимание!

EDIT:

Я загрузил другой скриншот Appstats. Это «обычный» запрос, который обычно занимает несколько сотен мс для запуска (макс. 1 сек.), А также в localhost (разработка). Я не могу найти что-нибудь, чтобы отлаживать дальше. Я чувствую, что мне не хватает чего-то простого, что-то на базовом уровне, в отношении ДО и НЕ НЕ ИСПОЛЬЗУЕТСЯ к движку приложения.

Answer 1

Учитывая, что это происходит нечасто, и что фактическое время обработки (указанные длины пролетов) короткие, мои подозрения в том, что какой-то App Engine масштабирования действие происходит в фоновом режиме. Например, замедление может быть вызвано добавлением нового экземпляра в ваше приложение. Вы можете углубиться в это, посмотрев график активности на панели приложений App Engine или используя AppStats (см. this SO post).

Отображение событий App Engine в виде временной шкалы трассировки - это то, что мы хотели бы сделать какое-то время, так как это резко сократило бы процесс анализа для таких ситуаций.

Answer 2

Я в курсе следующих общих причин таких пробелов («нетрассируемое время»):

• Запрос фактически CPU-связанные в течение этих промежутков.

  Чтобы проверить эту проблему, перейдите в окно просмотра журналов и просмотрите информацию о входящем HTTP-запросе. Обратите внимание, что есть также удобная прямая ссылка из данных трассировки на запись журнала . В записи журнала запроса, обратите внимание на cpu_ms поля, в котором говорится о

  миллисекунды CPU, необходимой для выполнения запроса. Это количество миллисекунд, затрачиваемых процессором, фактически выполняющим код вашего приложения, выраженный в терминах базового 1,2 ГГц процессора Intel x86. Если фактически используемый ЦП быстрее базовой линии, миллисекунды ЦП могут быть больше фактического времени [..]. (doc).

  Этот показатель также доступен в protoPayload.megaCycles.

  Вот пример записи журнала медленного запроса со значительным нетрассируемом время:

  2001:... - - [02/Mar/2017:19:20:22 +0100] "GET/HTTP/1.1" 200 660 - "Mozilla/5.0 ..." "example.com" ms=4966 **cpu_ms=11927** cpm_usd=7.376e-8 loading_request=1 instance=... app_engine_release=1.9.48 trace_id=... 
  

  В cpu_ms поле unusally высокой() для этого примера запроса, и указывает на то, что большинство из внеисто рической время проводилось в самом приложении (или во время выполнения).

  Почему обработчик запросов использует этот много процессор? Как правило, практически невозможно точно определить время, затрачиваемое процессором, но если вы знаете, что должно произойти в данном запросе, вы можете сгладить его более легко. Существуют две распространенные причины:

  • Это первый запрос к недавно запущенному экземпляру App Engine. JVM необходимо загружать классы и JIT-компилировать горячие методы - ожидается, что это значительно повлияет на первый запрос (и, возможно, еще несколько). Ищите load_request = 1 в записи журнала запросов, чтобы проверить, был ли ваш запрос медленным из-за этого. Рассмотрим Configuring Warmup Requests to Improve Performance.

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

    protoPayload.megaCycles > 10000 and protoPayload.wasLoadingRequest=false 
    

  • Некоторые части кода приложения массово замедляются чрезмерное использование рефлексии. Это относится к стандартной среде App Engine, где менеджер безопасности ограничивает использование рефлексии. Только смягчение состоит в том, чтобы использовать меньшее отражение. Обратите внимание, что инфраструктура обслуживания App Engine постоянно развивается, поэтому этот намек, возможно, будет устаревшим раньше, чем позже.

    Если проблема воспроизводится локально в dev appserver, вы можете использовать профайлер (или, может быть, просто jstack), чтобы сузить его. В некоторых других случаях я буквально должен был поэтапно делить пополам код приложения, добавлять больше операторов журнала, передислоцировать и т. Д., Пока не будет идентифицирован код нарушения.

• Есть на самом деле нетрассируемом звонки на движки, которые не покрываются из коробки с помощью Stackdriver трассировки в App Engine Standard окружающей среды. Единственным примером, о котором я знаю, является Cloud SQL. Рассмотрите возможность использования Google Cloud Trace for JDBC, чтобы получить взаимодействие с облачным SQL-трассировкой.

• Приложение многопоточное (отлично!) И испытывает некоторые проблемы с собственной собственной синхронизацией. Примеры, которые я видел в дикой природе:

  • Синхронизация, специфичная для приложения, заставляет все запросы к серверу хранения данных быть сериализованы (для данного экземпляра App Engine). Ничто не торчит в следах, кроме таинственных пробелов ...
  • Приложение использует пул соединений с базой данных. Количество параллельных запросов превышает емкость пула (для данного экземпляра App Engine), некоторые запросы должны ждать, пока соединение станет доступным. Это более сложный вариант предыдущего элемента.