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 google-appengine+unsubscr...@googlegroups.com. To post to this group, send email to google-appengine@googlegroups.com. 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/3f36917b-a97b-4f88-ac18-c426ca1ab0cd%40googlegroups.com. For more options, visit https://groups.google.com/d/optout.
