gae_ts_mon: instrument Cloud Endpoint methods

gae_ts_mon: instrument Cloud Endpoint methods

Introducing a decorator to instrument Cloud Endpoints methods.

In this version, only status and latency are measured. I'm not yet sure
how to extract request & response sizes; they are probably not accurately
known at the method level.

BUG=570410
R=dsansome@chromium.org,nodir@chromium.org

Committed: https://chromium.googlesource.com/infra/infra/+/d6c85d91f53ea782469c4ea76345d522c37077c2

[Sergey Berezin, 2016-03-15 00:25:55]

PTAL.

+nodir, because I borrowed his idea of decorators.

I haven't yet tested it on an actual Cloud Endpoint, this comes next (tomorrow).
But the tests pass.

[dsansome, 2016-03-15 02:01:20]

lgtm

https://codereview.chromium.org/1797103003/diff/20001/appengine_module/gae_ts...
File appengine_module/gae_ts_mon/config.py (right):

https://codereview.chromium.org/1797103003/diff/20001/appengine_module/gae_ts...
appengine_module/gae_ts_mon/config.py:172: def update_metrics(name,
response_status, elapsed_ms,
This name is quite generic.  Maybe update_http_server_metrics?
Also, maybe move it to http_metrics.py, since it might be useful outside
appengine as well?

https://codereview.chromium.org/1797103003/diff/20001/appengine_module/gae_ts...
File appengine_module/gae_ts_mon/test/config_test.py (right):

https://codereview.chromium.org/1797103003/diff/20001/appengine_module/gae_ts...
appengine_module/gae_ts_mon/test/config_test.py:354: 
nit: delete 1 \n

[nodir, 2016-03-15 18:59:49]

https://codereview.chromium.org/1797103003/diff/20001/appengine_module/gae_ts...
File appengine_module/gae_ts_mon/config.py (right):

https://codereview.chromium.org/1797103003/diff/20001/appengine_module/gae_ts...
appengine_module/gae_ts_mon/config.py:249: flush_thread.start()
check if it is needed in this thread, do not create a thread in every request

https://codereview.chromium.org/1797103003/diff/20001/appengine_module/gae_ts...
appengine_module/gae_ts_mon/config.py:263: update_metrics(method_name,
response_status, elapsed_ms)
there may be different endpoint services with clashing method names.
I'd prefer it to be actual URL
/_ah/spi/<service>.<method>
e.g. /_ah/spi/BuildBucketApi.search (this is a actual URL for buildbucket
search)

this first parameter of decorated is the service, you can get the class name
there. Also you can retrieve request headers, including user agent, maybe
request size, etc

[Sergey Berezin, 2016-03-17 22:14:04]

Responded to comments, and also tested on an actual app:
http://shortn/_CDDiUmmPn0

(code is here: http://crrev.com/1757213002)

BTW, notice the drop in the request latency: I bet that's due to avoiding the
unnecessary creation of the thread.

https://codereview.chromium.org/1797103003/diff/20001/appengine_module/gae_ts...
File appengine_module/gae_ts_mon/config.py (right):

https://codereview.chromium.org/1797103003/diff/20001/appengine_module/gae_ts...
appengine_module/gae_ts_mon/config.py:172: def update_metrics(name,
response_status, elapsed_ms,
On 2016/03/15 02:01:20, dsansome wrote:
> This name is quite generic.  Maybe update_http_server_metrics?
> Also, maybe move it to http_metrics.py, since it might be useful outside
> appengine as well?

Good idea, done.

https://codereview.chromium.org/1797103003/diff/20001/appengine_module/gae_ts...
appengine_module/gae_ts_mon/config.py:249: flush_thread.start()
On 2016/03/15 18:59:49, nodir wrote:
> check if it is needed in this thread, do not create a thread in every request

Done here and in the regular endpoint instrumentation.

https://codereview.chromium.org/1797103003/diff/20001/appengine_module/gae_ts...
appengine_module/gae_ts_mon/config.py:263: update_metrics(method_name,
response_status, elapsed_ms)
On 2016/03/15 18:59:49, nodir wrote:
> there may be different endpoint services with clashing method names.
> I'd prefer it to be actual URL
> /_ah/spi/<service>.<method>
> e.g. /_ah/spi/BuildBucketApi.search (this is a actual URL for buildbucket
> search)

Good catch, done.

> this first parameter of decorated is the service, you can get the class name
> there. Also you can retrieve request headers, including user agent, maybe
> request size, etc

This requires more assumptions about the method arguments; I'm inclined to do
this in another CL.

https://codereview.chromium.org/1797103003/diff/20001/appengine_module/gae_ts...
File appengine_module/gae_ts_mon/test/config_test.py (right):

https://codereview.chromium.org/1797103003/diff/20001/appengine_module/gae_ts...
appengine_module/gae_ts_mon/test/config_test.py:354: 
On 2016/03/15 02:01:20, dsansome wrote:
> nit: delete 1 \n

Done.

[dsansome, 2016-03-18 02:50:03]

Description was changed from

==========
gae_ts_mon: instrument Cloud Endpoint methods

Introducing a decorator to instrument Cloud Endpoints methods.

In this version, only status and latency are measured. I'm not yet sure
how to extract request & response sizes; they are probably not accurately
known at the method level.

BUG=None
R=dsansome@chromium.org,nodir@chromium.org
==========

to

==========
gae_ts_mon: instrument Cloud Endpoint methods

Introducing a decorator to instrument Cloud Endpoints methods.

In this version, only status and latency are measured. I'm not yet sure
how to extract request & response sizes; they are probably not accurately
known at the method level.

BUG=570410
R=dsansome@chromium.org,nodir@chromium.org
==========

[nodir, 2016-03-18 17:38:02]

https://codereview.chromium.org/1797103003/diff/80001/appengine_module/gae_ts...
File appengine_module/gae_ts_mon/config.py (right):

https://codereview.chromium.org/1797103003/diff/80001/appengine_module/gae_ts...
appengine_module/gae_ts_mon/config.py:43: def
need_to_flush_metrics(time_fn=time.time):
I'd add a docstring that this function is not pure as the func name my falsly
imply

https://codereview.chromium.org/1797103003/diff/80001/appengine_module/gae_ts...
appengine_module/gae_ts_mon/config.py:49: interface.state.last_flushed =
time_now
What happens if flushing fails after this value is changed?

https://codereview.chromium.org/1797103003/diff/80001/appengine_module/gae_ts...
appengine_module/gae_ts_mon/config.py:56: return
_flush_metrics(interface.state.last_flushed)
passing last_flushed as time_now seems to heavily rely on the fact that
need_to_flush_metrics assigns it to time_fn(), which is an abstraction leak. I'd
save time_fn() to a variable, pass it to need_to_flush_metrics and
_flush_metrics

https://codereview.chromium.org/1797103003/diff/80001/appengine_module/gae_ts...
appengine_module/gae_ts_mon/config.py:200: flush_thread.join()
please join after elapsed_ms is computed

https://codereview.chromium.org/1797103003/diff/80001/appengine_module/gae_ts...
appengine_module/gae_ts_mon/config.py:260: flush_thread.join()
same here

[Sergey Berezin, 2016-03-21 18:49:32]

PTAL, thanks for great comments!

https://codereview.chromium.org/1797103003/diff/80001/appengine_module/gae_ts...
File appengine_module/gae_ts_mon/config.py (right):

https://codereview.chromium.org/1797103003/diff/80001/appengine_module/gae_ts...
appengine_module/gae_ts_mon/config.py:43: def
need_to_flush_metrics(time_fn=time.time):
On 2016/03/18 17:38:02, nodir wrote:
> I'd add a docstring that this function is not pure as the func name my falsly
> imply

Done.

https://codereview.chromium.org/1797103003/diff/80001/appengine_module/gae_ts...
appengine_module/gae_ts_mon/config.py:49: interface.state.last_flushed =
time_now
On 2016/03/18 17:38:02, nodir wrote:
> What happens if flushing fails after this value is changed?

We simply retry a minute later. This in fact is a feature, as otherwise we'd be
needlessly affecting every user request e.g. during brief PubSub outages.

https://codereview.chromium.org/1797103003/diff/80001/appengine_module/gae_ts...
appengine_module/gae_ts_mon/config.py:56: return
_flush_metrics(interface.state.last_flushed)
On 2016/03/18 17:38:02, nodir wrote:
> passing last_flushed as time_now seems to heavily rely on the fact that
> need_to_flush_metrics assigns it to time_fn(), which is an abstraction leak.
I'd
> save time_fn() to a variable, pass it to need_to_flush_metrics and
> _flush_metrics

Very good point, thanks. I refactored this part of the code.

https://codereview.chromium.org/1797103003/diff/80001/appengine_module/gae_ts...
appengine_module/gae_ts_mon/config.py:200: flush_thread.join()
On 2016/03/18 17:38:02, nodir wrote:
> please join after elapsed_ms is computed

This is on purpose: I want to track the total request time including the
monitoring overhead. Otherwise we may miss ts_mon regressions.

https://codereview.chromium.org/1797103003/diff/80001/appengine_module/gae_ts...
appengine_module/gae_ts_mon/config.py:260: flush_thread.join()
On 2016/03/18 17:38:02, nodir wrote:
> same here

Same response as above.

[nodir, 2016-03-21 19:16:02]

lgtm

[Sergey Berezin, 2016-03-21 19:23:04]

The CQ bit was checked by sergeyberezin@chromium.org

[Sergey Berezin, 2016-03-21 19:23:05]

The patchset sent to the CQ was uploaded after l-g-t-m from
dsansome@chromium.org
Link to the patchset: https://codereview.chromium.org/1797103003/#ps120001
(title: "Use fake time in shutdown hook test")

[commit-bot: I haz the power, 2016-03-21 19:23:17]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1797103003/120001
View timeline at
 https://chromium-cq-status.appspot.com/patch-timeline/1797103003/120001

[commit-bot: I haz the power, 2016-03-21 19:28:25]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-03-21 19:28:27]

Try jobs failed on following builders:
  Infra Linux Precise 32 Tester on tryserver.infra (JOB_FAILED,
https://build.chromium.org/p/tryserver.infra/builders/Infra%20Linux%20Precise...)

[Sergey Berezin, 2016-03-22 00:28:17]

The CQ bit was checked by sergeyberezin@chromium.org

[Sergey Berezin, 2016-03-22 00:28:17]

The patchset sent to the CQ was uploaded after l-g-t-m from
dsansome@chromium.org, nodir@chromium.org
Link to the patchset: https://codereview.chromium.org/1797103003/#ps140001
(title: "Fixed the failing tests")

[commit-bot: I haz the power, 2016-03-22 00:28:21]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1797103003/140001
View timeline at
 https://chromium-cq-status.appspot.com/patch-timeline/1797103003/140001

[commit-bot: I haz the power, 2016-03-22 00:33:36]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-03-22 00:33:37]

Try jobs failed on following builders:
  Infra Linux Precise 32 Tester on tryserver.infra (JOB_FAILED,
https://build.chromium.org/p/tryserver.infra/builders/Infra%20Linux%20Precise...)

[Sergey Berezin, 2016-03-24 19:42:59]

The CQ bit was checked by sergeyberezin@chromium.org

[Sergey Berezin, 2016-03-24 19:43:00]

The patchset sent to the CQ was uploaded after l-g-t-m from
dsansome@chromium.org, nodir@chromium.org
Link to the patchset: https://codereview.chromium.org/1797103003/#ps200001
(title: "Reduced test flakiness")

[commit-bot: I haz the power, 2016-03-24 19:43:10]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1797103003/200001
View timeline at
 https://chromium-cq-status.appspot.com/patch-timeline/1797103003/200001

[commit-bot: I haz the power, 2016-03-24 19:46:29]

Description was changed from

==========
gae_ts_mon: instrument Cloud Endpoint methods

Introducing a decorator to instrument Cloud Endpoints methods.

In this version, only status and latency are measured. I'm not yet sure
how to extract request & response sizes; they are probably not accurately
known at the method level.

BUG=570410
R=dsansome@chromium.org,nodir@chromium.org
==========

to

==========
gae_ts_mon: instrument Cloud Endpoint methods

Introducing a decorator to instrument Cloud Endpoints methods.

In this version, only status and latency are measured. I'm not yet sure
how to extract request & response sizes; they are probably not accurately
known at the method level.

BUG=570410
R=dsansome@chromium.org,nodir@chromium.org

Committed:
https://chromium.googlesource.com/infra/infra/+/d6c85d91f53ea782469c4ea76345d...
==========

[commit-bot: I haz the power, 2016-03-24 19:46:30]

Committed patchset #11 (id:200001) as
https://chromium.googlesource.com/infra/infra/+/d6c85d91f53ea782469c4ea76345d...

[Sergiy Byelozyorov, 2016-03-24 20:09:36]

A revert of this CL (patchset #11 id:200001) has been created in
https://codereview.chromium.org/1829023003/ by sergiyb@chromium.org.

The reason for reverting is: Breaks all apps with the following error:

Configuration "webapp_django_version" not recognized

Traceback (most recent call last):
  File
"/base/data/home/runtimes/python27/python27_lib/versions/1/google/appengine/runtime/wsgi.py",
line 240, in Handle
    handler = _config_handle.add_wsgi_middleware(self._LoadHandler())
  File
"/base/data/home/runtimes/python27/python27_lib/versions/1/google/appengine/runtime/wsgi.py",
line 299, in _LoadHandler
    handler, path, err = LoadObject(self._handler)
  File
"/base/data/home/runtimes/python27/python27_lib/versions/1/google/appengine/runtime/wsgi.py",
line 85, in LoadObject
    obj = __import__(path[0])
  File
"/base/data/home/apps/s~chromium-try-flakes/3718-78083c5.391607094608479213/main.py",
line 5, in <module>
    import gae_ts_mon
  File
"/base/data/home/apps/s~chromium-try-flakes/3718-78083c5.391607094608479213/gae_ts_mon/__init__.py",
line 38, in <module>
    from infra_libs.ts_mon.config import initialize
  File
"/base/data/home/apps/s~chromium-try-flakes/3718-78083c5.391607094608479213/gae_ts_mon/config.py",
line 14, in <module>
    import endpoints
ImportError: No module named endpoints.