Ah ok - I see this now. For some reason I cant get hold of the log for this particular request, but I can see that most of my current endpoints are showing 0ms cpu_ms, which would suggest that they are optimal, and are always waiting on RPCs to complete? Is that correct?
I'll get more logging in the auth filter and see where that gets us! Thanks very much, Ben On Tuesday, 30 August 2016 21:44:57 UTC+1, Nick (Cloud Platform Support) wrote: > > Hey Ben, > > The cpu_ms and ms data can be found in the logs in the Developers' > Console. Let me know how the timing code works out! > > Cheers, > > Nick > Cloud Platform Community Support > > On Monday, August 22, 2016 at 7:36:41 AM UTC-4, Ben Rometsch wrote: >> >> Hi Nick, >> >> I'm not sure where to find the cpu_ms vs ms times? Can you point me to >> where I would find that? >> >> We're using cloud endpoints, so I think the logging is being managed by >> that library as opposed to us doing any specific logging. >> >> It's possible the AuthFilter could be waiting on FB - I'll add some >> logging in there to see. >> >> Thanks for your help. >> >> On Friday, 19 August 2016 20:03:22 UTC+1, Nick (Cloud Platform Support) >> wrote: >>> >>> Hey Ben, >>> >>> Thanks for the quick reply. Did you manage to check the "cpu_ms" vs "ms" >>> for the request log in question? >>> >>> As for the way to read the trace, I think the info log tags are showing >>> up in the timeline when the method completes (with a slight logging delay) >>> rather than when it starts, as evidenced also by the pattern of the other >>> method calls. The rectangles show the duration of the method, while the >>> info log tags are showing up in the timeline associated with these, but are >>> being inserted by another process. Do you have some sort of config turned >>> on to log all method calls? >>> >>> Finally, does the auth filter code require some intensive CPU or a >>> network call? >>> >>> Cheers, >>> >>> Nick >>> Cloud Platform Community Support >>> >>> On Friday, August 19, 2016 at 6:07:01 AM UTC-4, Ben Rometsch wrote: >>>> >>>> Thanks for the reply Nick. >>>> >>>> I dont think I was clear in my previous post, but when I think the logs >>>> are showing is that the call into the AuthFilter is stalling for around >>>> 1000ms before it actually starts into that method. I'm not sure what could >>>> be causing that delay? Or maybe I'm reading this screen wrong? >>>> >>>> On Wednesday, 17 August 2016 10:19:17 UTC+1, Ben Rometsch wrote: >>>>> >>>>> We are running a Java Cloud Endpoints API on Flexible VMs. Most of the >>>>> endpoints complete in a timely manner, but from time to time we see >>>>> things >>>>> like the attached in the trace: >>>>> >>>>> >>>>> <https://lh3.googleusercontent.com/-EVHbof4Fxos/V7QqlP--HaI/AAAAAAAAnTU/Hyh1F07ym6sM9KpvAuGxysgKp-xNze9lwCLcB/s1600/screenshot_201608171471424924.png> >>>>> >>>>> >>>>> Does anyone know why/what the platform is doing in the first 1000ms? >>>>> We have an AuthFilter that runs to check users are authenticated, but >>>>> normally this runs quickly at the start of the request. We have some API >>>>> urls that dont go through Cloud Endpoints and they don't exhibit this >>>>> issue, so are suspicious that its the cloud endpoints but we are not >>>>> sure? >>>>> >>>> -- You received this message because you are subscribed to the Google Groups "Google App Engine" group. To unsubscribe from this group and stop receiving emails from it, send an email to [email protected]. To post to this group, send email to [email protected]. Visit this group at https://groups.google.com/group/google-appengine. To view this discussion on the web visit https://groups.google.com/d/msgid/google-appengine/dffec86b-8119-4595-9b9e-144a59fc0e86%40googlegroups.com. For more options, visit https://groups.google.com/d/optout.
