Hi Waleed, You may find this blog post useful for explaining the various fields of log entries: http://blog.notdot.net/2011/06/Demystifying-the-App-Engine-request-logs
pending_ms is the amount of time the request spent waiting on an app server to become available to execute the task. -Nick Johnson On Wed, Jun 22, 2011 at 8:45 AM, Waleed Abdulla <wal...@ninua.com> wrote: > Good catch, thanks. I'm guessing that pending_ms is the time a request > stays on hold before execution? I couldn't find it documented anywhere. If > so, then the question is: why would a request be in a pending state? Is it > waiting for an instance to be free? > > This might also be related to my other thread about the task queue not > scaling up [1]. > > Thanks, > Waleed > > [1] > http://groups.google.com/group/google-appengine/browse_thread/thread/f8d1c6f39ad2af27/c989b852d1011cd6 > > > > > > On Tue, Jun 21, 2011 at 3:33 PM, Nicholas Verne <nve...@google.com> wrote: > >> One other note: >> >> In a large number of cases, if you the pending_ms (when it exists) to >> your measurement, you come close to the ms value you circled at the >> top. >> >> Nick Verne >> >> On Wed, Jun 22, 2011 at 8:18 AM, Nicholas Verne <nve...@google.com> >> wrote: >> > Waleed, >> > >> > I'm going to have to ask one of the other infrastructure engineers >> > about the log lines. The value you have circled (18386ms) is not >> > always greater than the cpu_ms. I'm not sure what this value >> > indicates. >> > >> > Nick Verne >> > >> > On Wed, Jun 22, 2011 at 6:27 AM, Waleed Abdulla <wal...@ninua.com> >> wrote: >> >> Nicholas, >> >> I implemented the change you suggested (making task_t0) a global >> >> variable, but that didn't change the calculations. I'm attaching >> another >> >> screen shot. There is a big difference between the actual processing >> time >> >> and the time reported in the logs. It doesn't happen in all tasks, but >> it's >> >> often enough that it's slowing down my application considerably and >> causing >> >> a lot of user complaints. >> >> I also calculated the total time to load the module (including time >> for >> >> imports). It doesn't seem to take much time (sub 1 second), and it >> happens >> >> only once right after I deploy a new version. So that is not an issue. >> >> I've set the processing rate, bucket size, and max concurrency on >> the >> >> task queue to high numbers (much higher than I need). >> >> Any explanation for why this is happening? >> >> Waleed >> >> >> >> >> >> >> >> On Mon, Jun 20, 2011 at 6:54 PM, Brandon Wirtz <drak...@digerat.com> >> wrote: >> >>> >> >>> Use a fetch from one thread to another. >> >>> >> >>> Echo Time >> >>> Fetch >> >>> Echo Time >> >>> Do something >> >>> Echo Time >> >>> Echo Fetch >> >>> >> >>> Now you have a timeline of everything except the latency from User to >> >>> Appengine. >> >>> >> >>> >> >>> -----Original Message----- >> >>> From: google-appengine@googlegroups.com >> >>> [mailto:google-appengine@googlegroups.com] On Behalf Of Nicholas >> Verne >> >>> Sent: Monday, June 20, 2011 6:03 PM >> >>> To: google-appengine@googlegroups.com >> >>> Subject: Re: [google-appengine] Why a big difference between execution >> >>> time >> >>> and response time? >> >>> >> >>> Yes, that's true. If you try this: >> >>> >> >>> task_t0 = None >> >>> >> >>> ... >> >>> >> >>> >> >>> def main(argv): >> >>> global task_t0 >> >>> task_t0 = time.time() >> >>> >> >>> You'll get a measurement per request as early as we can make it. For >> >>> warming >> >>> requests, it might still be worth measuring the import time >> >>> >> >>> import time >> >>> import_start = time.time() >> >>> ... other imports >> >>> import_duration = time.time() - import_start >> >>> >> >>> The import_duration global should persist and tell you how long this >> >>> instance's imports took to process. Subsequent requests on that >> instance >> >>> don't do the imports. >> >>> >> >>> Nick Verne >> >>> >> >>> On Tue, Jun 21, 2011 at 10:49 AM, Waleed Abdulla <wal...@ninua.com> >> wrote: >> >>> >> A more useful measurement might be to set task_t0 as a global >> >>> >> variable at the top of your file, with only the import of "time" >> >>> >> preceding it >> >>> > >> >>> > Wouldn't that cause the 2nd, 3rd, ...nth requests to the same >> handler >> >>> > to show wrong values? I see why setting task_t0 at the top of the >> file >> >>> > would apply if it was the first request that causes the handler to >> be >> >>> > loaded. But this is happening on an ongoing basis for all requests, >> >>> > not only the first for that handler. >> >>> > >> >>> > -- >> >>> > You received this message because you are subscribed to the Google >> >>> > Groups "Google App Engine" group. >> >>> > To post to this group, send email to >> google-appengine@googlegroups.com. >> >>> > To unsubscribe from this group, send email to >> >>> > google-appengine+unsubscr...@googlegroups.com. >> >>> > For more options, visit this group at >> >>> > http://groups.google.com/group/google-appengine?hl=en. >> >>> > >> >>> >> >>> -- >> >>> You received this message because you are subscribed to the Google >> Groups >> >>> "Google App Engine" group. >> >>> To post to this group, send email to >> google-appengine@googlegroups.com. >> >>> To unsubscribe from this group, send email to >> >>> google-appengine+unsubscr...@googlegroups.com. >> >>> For more options, visit this group at >> >>> http://groups.google.com/group/google-appengine?hl=en. >> >>> >> >>> >> >>> -- >> >>> You received this message because you are subscribed to the Google >> Groups >> >>> "Google App Engine" group. >> >>> To post to this group, send email to >> google-appengine@googlegroups.com. >> >>> To unsubscribe from this group, send email to >> >>> google-appengine+unsubscr...@googlegroups.com. >> >>> For more options, visit this group at >> >>> http://groups.google.com/group/google-appengine?hl=en. >> >>> >> >> >> >> -- >> >> You received this message because you are subscribed to the Google >> Groups >> >> "Google App Engine" group. >> >> To post to this group, send email to google-appengine@googlegroups.com >> . >> >> To unsubscribe from this group, send email to >> >> google-appengine+unsubscr...@googlegroups.com. >> >> For more options, visit this group at >> >> http://groups.google.com/group/google-appengine?hl=en. >> >> >> > >> >> -- >> You received this message because you are subscribed to the Google Groups >> "Google App Engine" group. >> To post to this group, send email to google-appengine@googlegroups.com. >> To unsubscribe from this group, send email to >> google-appengine+unsubscr...@googlegroups.com. >> For more options, visit this group at >> http://groups.google.com/group/google-appengine?hl=en. >> >> > -- > You received this message because you are subscribed to the Google Groups > "Google App Engine" group. > To post to this group, send email to google-appengine@googlegroups.com. > To unsubscribe from this group, send email to > google-appengine+unsubscr...@googlegroups.com. > For more options, visit this group at > http://groups.google.com/group/google-appengine?hl=en. > -- Nick Johnson, Developer Programs Engineer, App Engine -- You received this message because you are subscribed to the Google Groups "Google App Engine" group. To post to this group, send email to google-appengine@googlegroups.com. To unsubscribe from this group, send email to google-appengine+unsubscr...@googlegroups.com. For more options, visit this group at http://groups.google.com/group/google-appengine?hl=en.
